import time doubled by master vs 1.4.3

efiring · September 8, 2015, 7:30pm

test:

time python -c "from matplotlib import pyplot"

On a linux VM with Py 3.4 the user time is around

0.25 s for 1.4.3
0.5 s for master

That's quite a difference. Can anyone else reproduce this? Any ideas
as to what is causing the slowdown?

In both tests the backend was tkagg, so the difference was not a matter
of importing different gui toolkits.

Eric

tacaswell · September 8, 2015, 7:51pm

My guess is that this has to do with disk access? With venvs running on a
ramdisk I get almost identical times, particularly if I run it a couple of
times:

15:39 $ time python -c "from matplotlib import pyplot; import matplotlib;
print(matplotlib.__version__)"
1.4.3

real 0m0.377s
user 0m0.343s
sys 0m0.030s

15:36 $ time python -c "from matplotlib import pyplot; import matplotlib;
print(matplotlib.__version__)"
1.5.dev1

real 0m0.362s
user 0m0.327s
sys 0m0.030s

Both of those times fluctuate and despite what I pasted, 1.4.3 seems to be
faster more often than not (but by hundredths of seconds).

Running this command several times seems the later runs seem to be faster
than the first time.

Tom

···

On Tue, Sep 8, 2015 at 3:30 PM Eric Firing <efiring at hawaii.edu> wrote:

test:

time python -c "from matplotlib import pyplot"

On a linux VM with Py 3.4 the user time is around

0.25 s for 1.4.3
0.5 s for master

That's quite a difference. Can anyone else reproduce this? Any ideas
as to what is causing the slowdown?

In both tests the backend was tkagg, so the difference was not a matter
of importing different gui toolkits.

Eric
_______________________________________________
Matplotlib-devel mailing list
Matplotlib-devel at python.org
Matplotlib-devel Info Page

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.python.org/pipermail/matplotlib-devel/attachments/20150908/40c2979a/attachment.html>

efiring · September 8, 2015, 8:42pm

My guess is that this has to do with disk access? With venvs running on
a ramdisk I get almost identical times, particularly if I run it a
couple of times:

15:39$ time python -c "from matplotlib import pyplot; import matplotlib;
print(matplotlib.__version__)"
1.4.3

real 0m0.377s
user 0m0.343s
sys 0m0.030s

15:36$ time python -c "from matplotlib import pyplot; import matplotlib;
print(matplotlib.__version__)"
1.5.dev1

real 0m0.362s
user 0m0.327s
sys 0m0.030s

Both of those times fluctuate and despite what I pasted, 1.4.3 seems to
be faster more often than not (but by hundredths of seconds).

Running this command several times seems the later runs seem to be
faster than the first time.

Running multiple times one does see variations, but not large ones
compared to the factor of two I am getting between the versions. My
environment is a virtualenv in a VMWare linux VM on a Mac, with the disk
access via VMWare's hgfs. The Mac has SSD, so the physical disk access
is quick; and at least some things will be retrieved from cache on
multiple runs. The tests were made using the same VM and the same
virtualenv, so the only thing that changed was whether I had just build
mpl from 1.4.3 or from master.

Now I have tried the experiment on the OSX side, and I get very similar
results, except that all the times are a little bit longer than on the
linux VM:

(python3)efiring at manini2:~/work/programs/py/ladcp_netcdf$ time python -c
"from matplotlib import pyplot; import matplotlib;
print(matplotlib.__version__)"
1.4.3

real 0m0.379s
user 0m0.321s
sys 0m0.055s

(testmpl3)efiring at manini2:~/work/programs/py/mpl/matplotlib$ time python
-c "from matplotlib import pyplot; import matplotlib;
print(matplotlib.__version__)"
1.5.dev1

real 0m0.795s
user 0m0.704s
sys 0m0.086s

I guess the fact that the linux VM on OSX is faster than native OSX
points to disk access in some form--maybe there is more caching on the
linux side--but the puzzle remains: why the factor of two difference
between 1.4.3 and master in these two reasonably normal configurations?

Eric

···

On 2015/09/08 9:51 AM, Thomas Caswell wrote:

Tom

On Tue, Sep 8, 2015 at 3:30 PM Eric Firing <efiring at hawaii.edu > <mailto:efiring at hawaii.edu>> wrote:

    test:

    time python -c "from matplotlib import pyplot"

    On a linux VM with Py 3.4 the user time is around

    0.25 s for 1.4.3
    0.5 s for master

    That's quite a difference. Can anyone else reproduce this? Any ideas
    as to what is causing the slowdown?

    In both tests the backend was tkagg, so the difference was not a matter
    of importing different gui toolkits.

    Eric
    _______________________________________________
    Matplotlib-devel mailing list
    Matplotlib-devel at python.org <mailto:Matplotlib-devel at python.org>
    Matplotlib-devel Info Page

njs · September 8, 2015, 8:51pm

"User" and "system" time are both measures of cpu time. Disk access shows
up in the difference between real - (user + sys). (Also disk access time is
never going to be measurable for a smallish read only workload like this
after the first time you run it, because the OS will cache everything in
RAM. If you want to measure disk access time then you need to drop caches
before each test. In the VM case I guess you might need to do this on both
the guest and host.)

Anyway a 300 ms difference in cpu time is pretty blatant, I'd just run it
under a profiler and see what pops up.

-n

···

On Sep 8, 2015 1:42 PM, "Eric Firing" <efiring at hawaii.edu> wrote:

On 2015/09/08 9:51 AM, Thomas Caswell wrote:

My guess is that this has to do with disk access? With venvs running on
a ramdisk I get almost identical times, particularly if I run it a
couple of times:

15:39$ time python -c "from matplotlib import pyplot; import matplotlib;
print(matplotlib.__version__)"
1.4.3

real 0m0.377s
user 0m0.343s
sys 0m0.030s

15:36$ time python -c "from matplotlib import pyplot; import matplotlib;
print(matplotlib.__version__)"
1.5.dev1

real 0m0.362s
user 0m0.327s
sys 0m0.030s

Both of those times fluctuate and despite what I pasted, 1.4.3 seems to
be faster more often than not (but by hundredths of seconds).

Running this command several times seems the later runs seem to be
faster than the first time.

Running multiple times one does see variations, but not large ones
compared to the factor of two I am getting between the versions. My
environment is a virtualenv in a VMWare linux VM on a Mac, with the disk
access via VMWare's hgfs. The Mac has SSD, so the physical disk access is
quick; and at least some things will be retrieved from cache on multiple
runs. The tests were made using the same VM and the same virtualenv, so the
only thing that changed was whether I had just build mpl from 1.4.3 or from
master.

Now I have tried the experiment on the OSX side, and I get very similar
results, except that all the times are a little bit longer than on the
linux VM:

(python3)efiring at manini2:~/work/programs/py/ladcp_netcdf$ time python -c
"from matplotlib import pyplot; import matplotlib;
print(matplotlib.__version__)"
1.4.3

real 0m0.379s
user 0m0.321s
sys 0m0.055s

(testmpl3)efiring at manini2:~/work/programs/py/mpl/matplotlib$ time python
-c "from matplotlib import pyplot; import matplotlib;
print(matplotlib.__version__)"
1.5.dev1

real 0m0.795s
user 0m0.704s
sys 0m0.086s

I guess the fact that the linux VM on OSX is faster than native OSX points
to disk access in some form--maybe there is more caching on the linux
side--but the puzzle remains: why the factor of two difference between
1.4.3 and master in these two reasonably normal configurations?

Eric

Tom

On Tue, Sep 8, 2015 at 3:30 PM Eric Firing <efiring at hawaii.edu >> <mailto:efiring at hawaii.edu>> wrote:

    test:

    time python -c "from matplotlib import pyplot"

    On a linux VM with Py 3.4 the user time is around

    0.25 s for 1.4.3
    0.5 s for master

    That's quite a difference. Can anyone else reproduce this? Any ideas
    as to what is causing the slowdown?

    In both tests the backend was tkagg, so the difference was not a
matter
    of importing different gui toolkits.

    Eric
    _______________________________________________
    Matplotlib-devel mailing list
    Matplotlib-devel at python.org <mailto:Matplotlib-devel at python.org>
    Matplotlib-devel Info Page

_______________________________________________
Matplotlib-devel mailing list
Matplotlib-devel at python.org
Matplotlib-devel Info Page

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.python.org/pipermail/matplotlib-devel/attachments/20150908/b064e1ac/attachment-0001.html>

efiring · September 8, 2015, 8:53pm

I ran

strace python -c "from matplotlib import pyplot" > ../tests/master.trace
2>&1
and similar for v1.4.3:

-rw-r--r-- 1 efiring efiring 448374 Sep 8 10:46 v143.trace
-rw-r--r-- 1 efiring efiring 774942 Sep 8 10:49 master.trace
(python3)efiring at manini4:~/work/programs/py/mpl/tests$ grep matplotlib
master.trace | wc
     899 4988 127344
(python3)efiring at manini4:~/work/programs/py/mpl/tests$ grep matplotlib
v143.trace | wc
     693 3890 99963
(python3)efiring at manini4:~/work/programs/py/mpl/tests$ grep stat
master.trace | wc
    4307 27785 463042
(python3)efiring at manini4:~/work/programs/py/mpl/tests$ grep stat
v143.trace | wc
    2381 14898 248260

Somehow, master seems to have nearly doubled the number of stat calls.
Maybe there is more circularity in the imports now?

Eric

···

On 2015/09/08 9:51 AM, Thomas Caswell wrote:

My guess is that this has to do with disk access? With venvs running on
a ramdisk I get almost identical times, particularly if I run it a
couple of times:

njs · September 8, 2015, 9:01pm

My guess is that this has to do with disk access? With venvs running on
a ramdisk I get almost identical times, particularly if I run it a
couple of times:

I ran

strace python -c "from matplotlib import pyplot" > ../tests/master.trace

2>&1

and similar for v1.4.3:

-rw-r--r-- 1 efiring efiring 448374 Sep 8 10:46 v143.trace
-rw-r--r-- 1 efiring efiring 774942 Sep 8 10:49 master.trace
(python3)efiring at manini4:~/work/programs/py/mpl/tests$ grep matplotlib

master.trace | wc

899 4988 127344
(python3)efiring at manini4:~/work/programs/py/mpl/tests$ grep matplotlib

v143.trace | wc

693 3890 99963
(python3)efiring at manini4:~/work/programs/py/mpl/tests$ grep stat

master.trace | wc

4307 27785 463042
(python3)efiring at manini4:~/work/programs/py/mpl/tests$ grep stat

v143.trace | wc

2381 14898 248260

Somehow, master seems to have nearly doubled the number of stat calls.

Maybe there is more circularity in the imports now?

Do you have the same number of entries on sys.path for the two
interpreters? Most stat calls at import are checking to see which directory
in sys.path has the requested items.

Do you have any reason to believe that stat calls are actually what's
taking time? The calls themselves should show up in system time, which is
not very different in your quoted numbers -- though there could be some
python level overhead for processing each stat call depending on what
you're doing (which would show up in user time). You can also use the -T
options to strace to record timing information (though of course it also
slows things down). But generally strace is not a great tool for
investigating user cpu time differences, because it only watches
user<->system transitions.

-n
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.python.org/pipermail/matplotlib-devel/attachments/20150908/4983505f/attachment.html>

···

On Sep 8, 2015 1:53 PM, "Eric Firing" <efiring at hawaii.edu> wrote:

On 2015/09/08 9:51 AM, Thomas Caswell wrote:

efiring · September 9, 2015, 1:16am

Nope. It's that master is pulling in ipython, if it can be found, even
when the backend is selected as agg at the start. This is via
install_repl_displayhook in pyplot.py.

There might be other factors, but this is the big one. I will turn this
into a github issue.

Eric

···

On 2015/09/08 9:51 AM, Thomas Caswell wrote:

My guess is that this has to do with disk access?

tacaswell · September 9, 2015, 1:48am

That would explain why I was not seeing it, I was testing in bare-bones
venvs that did not have IPython installed. I have a PR in to fix it.

···

On Tue, Sep 8, 2015 at 9:16 PM Eric Firing <efiring at hawaii.edu> wrote:

On 2015/09/08 9:51 AM, Thomas Caswell wrote:
> My guess is that this has to do with disk access?

Nope. It's that master is pulling in ipython, if it can be found, even
when the backend is selected as agg at the start. This is via
install_repl_displayhook in pyplot.py.

There might be other factors, but this is the big one. I will turn this
into a github issue.

Eric

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.python.org/pipermail/matplotlib-devel/attachments/20150909/35cde410/attachment.html>