1775197 - mach python has a large overhead

Status: NEW

(Firefox Build System :: Mach Core, defect, P3)

Description

[Mike Hommey [:glandium]]

STR:

$ echo > test.py
$ time ./mach python test.py
real	0m0.709s
user	0m0.570s
sys	0m0.130s

For comparison:

$ time python3 test.py
real	0m0.009s
user	0m0.009s
sys	0m0.001s

It's harder to measure with other commands, but this likely affects other commands.

Comment 1

[Mike Hommey [:glandium]]

$ (export MACH_BUILD_PYTHON_NATIVE_PACKAGE_SOURCE=none; time ./mach python test.py)
real	0m0.482s
user	0m0.383s
sys	0m0.089s

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:ahochheiden, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 3

[Michael Froman [:mjf]]

I think this may have gotten worse since the bug was filed (for my Ubuntu 22 machine):

mfroman@moz:~/mozilla/moz-central$ time python3 -c 'print("done")'
done

real	0m0.036s
user	0m0.031s
sys	0m0.007s

mfroman@moz:~/mozilla/moz-central$ time ./mach python -c 'print("done")'
done

real	0m10.082s
user	0m8.701s
sys	0m2.042s

In both cases, the "done" output appears quickly, albeit slightly slower with ./mach python. However, the ./mach python version spends a great deal of time after "done" output.

Comment 4

[Mike Hommey [:glandium]]

$ time ./mach python -c 'print("done")'
done

real	0m0.835s
user	0m0.681s
sys	0m0.176s

You may want to capture a profile of what it's doing (./mach --profile-command python -c 'print("done")')

Comment 5

[Michael Froman [:mjf]]

Attachment: mach_profile_python.cProfile

mfroman@moz:~/mozilla/moz-central$ ./mach --profile-command python -c 'print("done")'
done
Mach command profile created at "/home/mfroman/mozilla/moz-central/mach_profile_python.cProfile". To visualize, use snakeviz:
python3 -m pip install snakeviz
python3 -m snakeviz mach_profile_python.cProfile

Comment 6

[Michael Froman [:mjf]]

Interesting note: the times reported on my MacBook Pro are much closer to glandium's times.

MJF-MacBookPro:moz-central mfroman$ time python3 -c 'print("done")'
done

real	0m0.029s
user	0m0.013s
sys	0m0.012s

MJF-MacBookPro:moz-central mfroman$ time ./mach python -c 'print("done")'
done

real	0m0.830s
user	0m0.936s
sys	0m0.306s

Comment 7

[Mike Hommey [:glandium]]

(In reply to Michael Froman [:mjf] from comment #5)

Created attachment 9323404 [details]
mach_profile_python.cProfile

erf, the profile itself only accounts for 0.031s. I guess whatever is taking forever on your machine is happening after the profiler is disabled.

Comment 8

[Michael Froman [:mjf]]

I'll investigate my machine after I return from PTO (Mar 22), but I cloned a separate copy of m-c and the times match glandium's times. So there is something in that copy of the repo or obj-dir that causing the issue (which interestingly is getting progressively worse).

Comment 9

[Michael Froman [:mjf]]

(In reply to Michael Froman [:mjf] from comment #8)

I'll investigate my machine after I return from PTO (Mar 22), but I cloned a separate copy of m-c and the times match glandium's times. So there is something in that copy of the repo or obj-dir that causing the issue (which interestingly is getting progressively worse).

What didn't help:
./mach clobber --full ; hg purge --all

What did help:
hg pull central ; hg update tip ; ./mach bootstrap --application=browser

Sorry for the noise!