Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
Hi Sandro, On 01/08/2016 03:34 PM, Sandro Tosi wrote: has this change with the latest releases of matplotlib? No, apparently not: $ python3 test.py $ dir ~/.matplotlib /bin/ls: cannot access /home/nikratio/.matplotlib: No such file or directory $ printenv | grep MPL $ apt show python3-matplotlib | grep Version WARNING: apt does not have a stable CLI interface. Use with caution in scripts. Version: 1.5.1~rc1-1 > from the last reply, it seems that enabling the cache make mpl quick for you, so that would be the solution for this? As far as I can tell, matplotlib is slow because it does not use the cache without the user explicitly setting MPLCONFIGDIR. According to the documentation, it should default to ~/.matplotlib if MPLCONFIGDIR is not set. So yes, explicitly setting MPLCONFIGDIR to some value fixes the slow startup. However, it has the detrimental side-effect that it stops matplotlib from reading its configuration from ~/.config/matplotlib/matplotlibrc, so I would call it a workaround, not a solution. Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
has this change with the latest releases of matplotlib? from the last reply, it seems that enabling the cache make mpl quick for you, so that would be the solution for this? On Tue, Oct 20, 2015 at 4:19 PM, Nikolaus Rath wrote: > Hi Sandro, > > When running in a sid chroot using the TkAgg backend and python2, matplotlib > is not using the ~/.matplotlib directory to cache data. It can be made to > use it by setting $MPLCONFIGDIR=~/.matplotlib, but in that case it no longer > reads ~/.config/matplotlib/matplotlibrc. If data caching is enabled by > explicitly setting MPLCONFIGDIR, the slow startup problem no longer > manifests. > > Additionally, when using PySide instead of TkAgg, matplotlib crashes with a > segfault (I tried to clone this bug to make a separate report, but failed). > > Best, > -Nikolaus -- Sandro "morph" Tosi My website: http://matrixhasu.altervista.org/ Me at Debian: http://wiki.debian.org/SandroTosi G+: https://plus.google.com/u/0/+SandroTosi
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
Hi Sandro, When running in a sid chroot using the TkAgg backend and python2, matplotlib is not using the ~/.matplotlib directory to cache data. It can be made to use it by setting $MPLCONFIGDIR=~/.matplotlib, but in that case it no longer reads ~/.config/matplotlib/matplotlibrc. If data caching is enabled by explicitly setting MPLCONFIGDIR, the slow startup problem no longer manifests. Additionally, when using PySide instead of TkAgg, matplotlib crashes with a segfault (I tried to clone this bug to make a separate report, but failed). Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
there a lot of confusion going on, please post results only when you have them all: it's already hard to follow your process as it is, and multiple messages with just a small comment in addition is only making it worst :( so, your last tests, on which environment did you run them (chroot, jessie/wheezy/sid/else)? with what version of matplotlib? if it's sid, did you dist-upgrade first? it is advisable to continue your tests on a dist-upgraded sid, as it is likely the place we can get upstream to look into it. please report the deps section of reportbug --template python-matplotlib On Mon, Oct 19, 2015 at 7:06 PM, Nikolaus Rath wrote: > On 10/19/2015 10:07 AM, Nikolaus Rath wrote: >> >> I forgot to add: with >> >> export MPLCONFIGDIR=~/.matplotlib/ >> >> it works fine. > > > ... as far as start-up time is concerned. But it also stops reading > ~/.config/matplotlib/matplotlibrc (which is less good). > > > Best, > -Nikolaus -- Sandro Tosi (aka morph, morpheus, matrixhasu) My website: http://matrixhasu.altervista.org/ Me at Debian: http://wiki.debian.org/SandroTosi
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
On 10/19/2015 10:07 AM, Nikolaus Rath wrote: I forgot to add: with export MPLCONFIGDIR=~/.matplotlib/ it works fine. ... as far as start-up time is concerned. But it also stops reading ~/.config/matplotlib/matplotlibrc (which is less good). Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
I forgot to add: with export MPLCONFIGDIR=~/.matplotlib/ it works fine. It seems matplotlib just doesn't use the directory by default anymore. Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
On 10/19/2015 09:52 AM, Sandro Tosi wrote: On Mon, Oct 19, 2015 at 5:50 PM, Nikolaus Rath wrote: I don't get it. Does MPLCONFIGDIR have any effects beside determining the configuration file? http://matplotlib.org/faq/environment_variables_faq.html#envvar-MPLCONFIGDIR Ok, we're getting somewhere. For some reason, matplotlib doesn't seem to use any cache if I don't set MPLCONFIGDIR: $ rm -r empty; md empty $ export MPLCONFIGDIR=empty $ time python test.py real0m1.701s user0m1.656s sys 0m0.040s $ ls empty fontList.cache tex.cache/ $ time python test.py real0m0.262s user0m0.244s sys 0m0.016s So once the cache is there, it's fast. Without MPLCONFIGDIR, however: $ unset MPLCONFIGDIR $ rm -r ~/.matplotlib/ $ time python test.py real0m1.700s user0m1.656s sys 0m0.036s $ ls ~/.matplotlib /bin/ls: cannot access /home/nikratio/.matplotlib: No such file or directory As an aside: I think it really should have created this directory on its own (yeah, fallback on the temporary directory is documented, but that still seems like a bad idea because it gives bad performance by default to everyone who doesn't happen to look up the semantics of MPLCONFIGDIR). Probably subject for another bug. That said, in my case it doesn't work even if the directory is present: $ md ~/.matplotlib $ touch ~/.matplotlib/testfile $ time python test.py real0m1.760s user0m1.668s sys 0m0.084s $ ls ~/.matplotlib testfile $ time python test.py real0m1.706s user0m1.644s sys 0m0.060s $ echo "really?" > ~/.matplotlib/fontList.cache Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
On Mon, Oct 19, 2015 at 5:50 PM, Nikolaus Rath wrote: > I don't get it. Does MPLCONFIGDIR have any effects beside determining the > configuration file? http://matplotlib.org/faq/environment_variables_faq.html#envvar-MPLCONFIGDIR -- Sandro Tosi (aka morph, morpheus, matrixhasu) My website: http://matrixhasu.altervista.org/ Me at Debian: http://wiki.debian.org/SandroTosi
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
I noticed that so far I have only tried a wheezy chroot (no problem), a sid chroot (crashes, but probably an unrelated problem), and my standard jessie system (slow) - but not a clean jessie chroot. When testing in a clean jessie chroot, the problem did not appear either. I was also able to get it to work normally on my regular system by setting MPLCONFIGDIR to a different value: $ unset MPLCONFIGDIR $ strace -c python test.py 2>&1 | head -10 % time seconds usecs/call callserrors syscall -- --- --- - - 77.940.000212 0157838 4 lseek 8.820.24 0 6113 4495 open 4.410.12 0 20350 read 2.940.08 0 11010 1094 stat 2.570.07 0 1110 munmap 1.840.05 0 1409 mmap 1.470.04 0 3056 fstat 0.000.00 047 write $ MPLCONFIGDIR=empty strace -c python test.py 2>&1 | head -10% time seconds usecs/call callserrors syscall -- --- --- - - 45.240.19 0 5385 4489 open 35.710.15 0 1103 fstat 19.050.08 0 3386 lseek 0.000.00 0 3200 read 0.000.00 047 write 0.000.00 0 906 close 0.000.00 0 1419 1092 stat 0.000.00 052 6 lstat I don't get it. Does MPLCONFIGDIR have any effects beside determining the configuration file? $ ls -al ~/.config/matplotlib/ total 36 drwxr-xr-x 2 nikratio nikratio 4096 Oct 19 09:46 ./ drwxr-xr-x 42 nikratio nikratio 4096 Jul 20 08:27 ../ -rw-r--r-- 1 nikratio nikratio 24725 Oct 19 09:33 matplotlibrc $ ls -al ~/.matplotlib/ total 32 drwxr-xr-x 3 nikratio nikratio 4096 Oct 7 10:04 ./ drwxr-xr-x 73 nikratio nikratio 4096 Oct 19 09:41 ../ -rw-r--r-- 1 nikratio nikratio 19110 Oct 7 09:42 fontList.cache drwxr-xr-x 2 nikratio nikratio 4096 Oct 7 09:42 tex.cache/ Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
clone -1 python-matplotlib: QtAgg4 with PySide segfaults bye On 10/19/2015 08:52 AM, Sandro Tosi wrote: On Mon, Oct 19, 2015 at 4:50 PM, Nikolaus Rath wrote: On 10/17/2015 11:57 AM, Sandro Tosi wrote: I got something interesting using the -c option. On Jessie: do you have a chance to test this on the recently uploaded 1.5.0~rc2 (i need to have results on a recent version to be able to forward it upstream)? In a sid chroot I got: real0m1.076s user0m0.432s sys 0m0.060s Is that with Python 2 or Python 3? I tried it with Python 2 (so that we can compare with wheezy), but I'm just getting a crash: $ time /usr/bin/python test.py Segmentation fault hmmm, so are you sure you have a clean python/matplotlib env? It's a clean sid chroot, without even /home mounted. But this is probably a separate issue. When I get change the backend from Qt4Agg to TkAgg, it works. Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
On Mon, Oct 19, 2015 at 4:50 PM, Nikolaus Rath wrote: > On 10/17/2015 11:57 AM, Sandro Tosi wrote: >>> >>> I got something interesting using the -c option. On Jessie: >> >> >> do you have a chance to test this on the recently uploaded 1.5.0~rc2 >> (i need to have results on a recent version to be able to forward it >> upstream)? In a sid chroot I got: >> >> real0m1.076s >> user0m0.432s >> sys 0m0.060s > > > Is that with Python 2 or Python 3? I tried it with Python 2 (so that we can > compare with wheezy), but I'm just getting a crash: > > $ time /usr/bin/python test.py > Segmentation fault hmmm, so are you sure you have a clean python/matplotlib env? what backend are you using? > real0m0.350s > user0m0.324s > sys 0m0.016s > > This is with python-pyside (python-pyqt4 doesn't seem to exist in sid). i suppose QtAgg, try TkAgg >> (i lost time closing the window) > > > Uh? My test script should close on its own without the need for user > interaction. since you show(), that will open a window -- Sandro Tosi (aka morph, morpheus, matrixhasu) My website: http://matrixhasu.altervista.org/ Me at Debian: http://wiki.debian.org/SandroTosi
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
On 10/19/2015 08:57 AM, Sandro Tosi wrote: since you show(), that will open a window But I don't: $ tar xJf issue_796905.tar.xz $ grep show python-slowdown/test.py #plt.show() I got the test case from the original post: import matplotlib.pyplot as plt plt.plot([1, 2, 3]) plt.show() if you're using another one, please paste it here I already did, in https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=796905#37. Here's the link again: https://trialphaenergy.box.com/shared/static/atpj07qtvdlgwft4ppp0l6q0jmjfo2a7.xz (sorry for the ugly link) Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
>> since you show(), that will open a window > > > But I don't: > > $ tar xJf issue_796905.tar.xz > $ grep show python-slowdown/test.py > #plt.show() I got the test case from the original post: import matplotlib.pyplot as plt plt.plot([1, 2, 3]) plt.show() if you're using another one, please paste it here -- Sandro Tosi (aka morph, morpheus, matrixhasu) My website: http://matrixhasu.altervista.org/ Me at Debian: http://wiki.debian.org/SandroTosi
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
On 10/19/2015 08:52 AM, Sandro Tosi wrote: >Uh? My test script should close on its own without the need for user >interaction. > since you show(), that will open a window But I don't: $ tar xJf issue_796905.tar.xz $ grep show python-slowdown/test.py #plt.show() Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
On 10/17/2015 11:57 AM, Sandro Tosi wrote: I got something interesting using the -c option. On Jessie: do you have a chance to test this on the recently uploaded 1.5.0~rc2 (i need to have results on a recent version to be able to forward it upstream)? In a sid chroot I got: real0m1.076s user0m0.432s sys 0m0.060s Is that with Python 2 or Python 3? I tried it with Python 2 (so that we can compare with wheezy), but I'm just getting a crash: $ time /usr/bin/python test.py Segmentation fault real0m0.350s user0m0.324s sys 0m0.016s This is with python-pyside (python-pyqt4 doesn't seem to exist in sid). (i lost time closing the window) Uh? My test script should close on its own without the need for user interaction. Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
> I got something interesting using the -c option. On Jessie: do you have a chance to test this on the recently uploaded 1.5.0~rc2 (i need to have results on a recent version to be able to forward it upstream)? In a sid chroot I got: real0m1.076s user0m0.432s sys 0m0.060s (i lost time closing the window) and % time seconds usecs/call callserrors syscall -- --- --- - - 95.690.001021 1 1943 read 2.720.29 0 1624 1175 recvmsg 1.590.17 0 983 fstat 0.000.00 0 120 write 0.000.00 0 2818 2057 open 0.000.00 0 767 close 0.000.00 0 807 587 stat 0.000.00 0 57542 lstat 0.000.00 0 855 poll 0.000.00 0 1042 6 lseek -- Sandro Tosi (aka morph, morpheus, matrixhasu) My website: http://matrixhasu.altervista.org/ Me at Debian: http://wiki.debian.org/SandroTosi
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
On 10/05/2015 09:36 AM, Sandro Tosi wrote: On Mon, Oct 5, 2015 at 5:25 PM, Nikolaus Rath wrote: Well, it only happens when using matplotlib, so there's got to be some connection. this is one good connection indeed. does it happen only on py3k or on py2 as well? It happens on py2 as well. Here is an impressive example: Current jessie system: $ time /usr/bin/python test.py real0m2.385s user0m2.312s sys 0m0.064s Freshly bootstrapped wheezy chroot: $ time /usr/bin/python ./test.py real0m0.351s user0m0.320s sys 0m0.024s Do you have a suggestion what I could try? At the moment I'm seeing even trivial matplotlib scripts take much longer than they used to, while Python itself starts as quick as ever. That's why I think it's connected to MPL. you can strace with timing and following the child processes, with -f -ttt (f.e. you might found that that lseek()ing a cached file is not that an issue) at least you can pin point where the time is spent. Unfortunately there is no single call that sticks out - except that the Jessie version makes more than 10 times as many syscalls: $ ls -lh wheezy.log jessie.log -rw-r--r-- 1 nikratio nikratio 14M Oct 7 09:41 jessie.log -rw-r--r-- 1 nikratio nikratio 1.2M Oct 7 09:44 wheezy.log At the moment I still think that the delay is really due to the accumulated time taken by all these syscalls. I have put the complete testcase at https://trialphaenergy.box.com/shared/static/atpj07qtvdlgwft4ppp0l6q0jmjfo2a7.xz (sorry for the ugly link). Are you able to reproduce this? Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
On 10/07/2015 09:50 AM, Nikolaus Rath wrote: On 10/05/2015 09:36 AM, Sandro Tosi wrote: On Mon, Oct 5, 2015 at 5:25 PM, Nikolaus Rath wrote: Well, it only happens when using matplotlib, so there's got to be some connection. this is one good connection indeed. does it happen only on py3k or on py2 as well? It happens on py2 as well. Here is an impressive example: Current jessie system: $ time /usr/bin/python test.py real0m2.385s user0m2.312s sys0m0.064s Freshly bootstrapped wheezy chroot: $ time /usr/bin/python ./test.py real0m0.351s user0m0.320s sys0m0.024s Do you have a suggestion what I could try? At the moment I'm seeing even trivial matplotlib scripts take much longer than they used to, while Python itself starts as quick as ever. That's why I think it's connected to MPL. you can strace with timing and following the child processes, with -f -ttt (f.e. you might found that that lseek()ing a cached file is not that an issue) at least you can pin point where the time is spent. Unfortunately there is no single call that sticks out - except that the Jessie version makes more than 10 times as many syscalls: $ ls -lh wheezy.log jessie.log -rw-r--r-- 1 nikratio nikratio 14M Oct 7 09:41 jessie.log -rw-r--r-- 1 nikratio nikratio 1.2M Oct 7 09:44 wheezy.log At the moment I still think that the delay is really due to the accumulated time taken by all these syscalls. I got something interesting using the -c option. On Jessie: $ strace -c /usr/bin/python2 test.py % time seconds usecs/call callserrors syscall -- --- --- - - 76.890.000163 0157839 4 lseek 14.150.30 0 20349 read 4.720.10 0 6114 4495 open 2.360.05 0 11007 1087 stat 1.890.04 0 3058 fstat 0.000.00 048 write 0.000.00 0 1763 close 0.000.00 0 176 6 lstat 0.000.00 0 112 poll 0.000.00 0 1413 mmap 0.000.00 0 147 mprotect 0.000.00 0 1115 munmap 0.000.00 0 165 brk [...] On Wheezy, on the other hand: $ strace -c /usr/bin/python2 test.py [...] % time seconds usecs/call callserrors syscall -- --- --- - - 100.000.04 0 469 mmap 0.000.00 0 1424 read 0.000.00 0 9 write 0.000.00 0 3924 3212 open 0.000.00 0 714 close 0.000.00 0 1223 997 stat 0.000.00 0 913 fstat So the lseek's seem to be making quite a relative impact. But according to the second column, none of the syscalls contributes anything relevant to the total execution time. At first I thought that this must mean that some of the forked subprocesses (e.g. fc-list) must thus be responsible. But that doesn't seem right either - if Python is waiting for the subprocess, surely this would show up as time spent in a read(), select(), or wait() syscall - wouldn't it? Best, -Nikolaus
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
On 10/5/2015 7:55 AM, Sandro Tosi wrote:
open("/usr/lib/python3.4/encodings/__pycache__/unicode_escape.cpython-34.pyc",
O_RDONLY|O_CLOEXEC) = 8
fstat(8, {st_mode=S_IFREG|0644, st_size=1842, ...}) = 0
lseek(8, 0, SEEK_CUR) = 0
fstat(8, {st_mode=S_IFREG|0644, st_size=1842, ...}) = 0
read(8,
"\356\f\r\n\240#5T\240\4\0\0\343\0\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0@\0\0"...,
1843) = 1842
read(8, "", 1) = 0
close(8)= 0
open("/usr/share/fonts/truetype/dejavu/DejaVuSans.ttf", O_RDONLY|O_CLOEXEC) = 8
fstat(8, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
ioctl(8, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS,
0x7ffe52ac0a90) = -1 ENOTTY (Inap
fstat(8, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
lseek(8, 0, SEEK_CUR) = 0
fcntl(8, F_DUPFD_CLOEXEC, 0)= 9
fcntl(9, F_GETFL) = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(9, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7f5403f06000
lseek(9, 0, SEEK_CUR) = 0
lseek(8, 0, SEEK_CUR) = 0
lseek(9, 0, SEEK_SET) = 0
fstat(9, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
lseek(9, 741376, SEEK_SET) = 741376
read(9, "+\0++"..., 160) = 160
lseek(9, 0, SEEK_SET) = 0
lseek(9, 0, SEEK_SET) = 0
lseek(9, 0, SEEK_SET) = 0
read(9, "\0\1\0\0\0\23\1\0\0\4\FFTMh\275QN\0\0\1<\0\0\0\34GDEF"..., 4096) =
4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
[...]
Note that there are no other syscalls between the lseek() - Python simply seeks
to the same position over and over again. I am not 100% sure that
this is the cause of the slow-down, but it certainly looks like
something is wrong here.
still nothing in the strace output is anything inside matplotlib: the
first line is a standard library module, and it's highly unlikely any
part of mpl is directly lseeking a font file (it's been dup()'ed).
Well, it only happens when using matplotlib, so there's got to be some
connection.
Additionally, you're testing on python3, python3-matplotlib has only
been shipped from jessie onward, so your claim that upgrading from
jessie made its performance poor, it's impossible.
You mean "upgrading from wheezy", right? Indeed, you're right. I believe
I actually updated from some post-wheezy testing snapshot to the jessie
release.
I'm afraid you will have to come up with something more related to mpl
that what's above, as it seems more a shot in the dark.
Do you have a suggestion what I could try? At the moment I'm seeing even
trivial matplotlib scripts take much longer than they used to, while
Python itself starts as quick as ever. That's why I think it's connected
to MPL.
Best,
-Nikolaus
--
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
On Mon, Oct 5, 2015 at 5:25 PM, Nikolaus Rath wrote: > Well, it only happens when using matplotlib, so there's got to be some > connection. this is one good connection indeed. does it happen only on py3k or on py2 as well? >> Additionally, you're testing on python3, python3-matplotlib has only >> been shipped from jessie onward, so your claim that upgrading from >> jessie made its performance poor, it's impossible. > > You mean "upgrading from wheezy", right? Indeed, you're right. I believe I yep > actually updated from some post-wheezy testing snapshot to the jessie > release. > >> I'm afraid you will have to come up with something more related to mpl >> that what's above, as it seems more a shot in the dark. > > Do you have a suggestion what I could try? At the moment I'm seeing even > trivial matplotlib scripts take much longer than they used to, while Python > itself starts as quick as ever. That's why I think it's connected to MPL. you can strace with timing and following the child processes, with -f -ttt (f.e. you might found that that lseek()ing a cached file is not that an issue) at least you can pin point where the time is spent. -- Sandro Tosi (aka morph, morpheus, matrixhasu) My website: http://matrixhasu.altervista.org/ Me at Debian: http://wiki.debian.org/SandroTosi
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
> open("/usr/lib/python3.4/encodings/__pycache__/unicode_escape.cpython-34.pyc",
> O_RDONLY|O_CLOEXEC) = 8
> fstat(8, {st_mode=S_IFREG|0644, st_size=1842, ...}) = 0
> lseek(8, 0, SEEK_CUR) = 0
> fstat(8, {st_mode=S_IFREG|0644, st_size=1842, ...}) = 0
> read(8,
> "\356\f\r\n\240#5T\240\4\0\0\343\0\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0@\0\0"...,
> 1843) = 1842
> read(8, "", 1) = 0
> close(8)= 0
> open("/usr/share/fonts/truetype/dejavu/DejaVuSans.ttf", O_RDONLY|O_CLOEXEC) =
> 8
> fstat(8, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
> ioctl(8, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS,
> 0x7ffe52ac0a90) = -1 ENOTTY (Inap
> fstat(8, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
> lseek(8, 0, SEEK_CUR) = 0
> fcntl(8, F_DUPFD_CLOEXEC, 0)= 9
> fcntl(9, F_GETFL) = 0x8000 (flags O_RDONLY|O_LARGEFILE)
> fstat(9, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
> 0x7f5403f06000
> lseek(9, 0, SEEK_CUR) = 0
> lseek(8, 0, SEEK_CUR) = 0
> lseek(9, 0, SEEK_SET) = 0
> fstat(9, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
> lseek(9, 741376, SEEK_SET) = 741376
> read(9, "+\0++"..., 160) = 160
> lseek(9, 0, SEEK_SET) = 0
> lseek(9, 0, SEEK_SET) = 0
> lseek(9, 0, SEEK_SET) = 0
> read(9, "\0\1\0\0\0\23\1\0\0\4\FFTMh\275QN\0\0\1<\0\0\0\34GDEF"..., 4096)
> = 4096
> lseek(9, 4096, SEEK_SET)= 4096
> lseek(9, 4096, SEEK_SET)= 4096
> lseek(9, 4096, SEEK_SET)= 4096
> lseek(9, 4096, SEEK_SET)= 4096
> lseek(9, 4096, SEEK_SET)= 4096
> lseek(9, 4096, SEEK_SET)= 4096
> lseek(9, 4096, SEEK_SET)= 4096
> lseek(9, 4096, SEEK_SET)= 4096
> lseek(9, 4096, SEEK_SET)= 4096
> lseek(9, 4096, SEEK_SET)= 4096
> [...]
>
> Note that there are no other syscalls between the lseek() - Python simply
> seeks to the same position over and over again. I am not 100% sure that
> this is the cause of the slow-down, but it certainly looks like
> something is wrong here.
still nothing in the strace output is anything inside matplotlib: the
first line is a standard library module, and it's highly unlikely any
part of mpl is directly lseeking a font file (it's been dup()'ed).
Additionally, you're testing on python3, python3-matplotlib has only
been shipped from jessie onward, so your claim that upgrading from
jessie made its performance poor, it's impossible.
I'm afraid you will have to come up with something more related to mpl
that what's above, as it seems more a shot in the dark.
Regards,
--
Sandro Tosi (aka morph, morpheus, matrixhasu)
My website: http://matrixhasu.altervista.org/
Me at Debian: http://wiki.debian.org/SandroTosi
Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow
Package: python3-matplotlib
Version: 1.4.2-3.1
Severity: normal
[ Apologies if this is a duplicate. I've submitted this yesterday already, but
never got an email confirmation nor does the bug show up on bugs.debian.org ]
Since upgrading from Wheezy, the startup of matplotlib seems extremely slow.
Scripts that previously appeared to show results instantanously now take
multiple seconds until the first plot appears.
I tried debugging this with a very simple test script:
#!/usr/bin/env python3
import matplotlib.pyplot as plt
plt.plot([1, 2, 3])
plt.show()
Looking at the strace output, I found a large number of seemingly
completely pointless lseek() calls. For example:
open("/usr/lib/python3.4/encodings/__pycache__/unicode_escape.cpython-34.pyc",
O_RDONLY|O_CLOEXEC) = 8
fstat(8, {st_mode=S_IFREG|0644, st_size=1842, ...}) = 0
lseek(8, 0, SEEK_CUR) = 0
fstat(8, {st_mode=S_IFREG|0644, st_size=1842, ...}) = 0
read(8,
"\356\f\r\n\240#5T\240\4\0\0\343\0\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0@\0\0"...,
1843) = 1842
read(8, "", 1) = 0
close(8)= 0
open("/usr/share/fonts/truetype/dejavu/DejaVuSans.ttf", O_RDONLY|O_CLOEXEC) = 8
fstat(8, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
ioctl(8, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS,
0x7ffe52ac0a90) = -1 ENOTTY (Inap
fstat(8, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
lseek(8, 0, SEEK_CUR) = 0
fcntl(8, F_DUPFD_CLOEXEC, 0)= 9
fcntl(9, F_GETFL) = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(9, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7f5403f06000
lseek(9, 0, SEEK_CUR) = 0
lseek(8, 0, SEEK_CUR) = 0
lseek(9, 0, SEEK_SET) = 0
fstat(9, {st_mode=S_IFREG|0644, st_size=741536, ...}) = 0
lseek(9, 741376, SEEK_SET) = 741376
read(9, "+\0++"..., 160) = 160
lseek(9, 0, SEEK_SET) = 0
lseek(9, 0, SEEK_SET) = 0
lseek(9, 0, SEEK_SET) = 0
read(9, "\0\1\0\0\0\23\1\0\0\4\FFTMh\275QN\0\0\1<\0\0\0\34GDEF"..., 4096) =
4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
lseek(9, 4096, SEEK_SET)= 4096
[...]
Note that there are no other syscalls between the lseek() - Python simply seeks
to the same position over and over again. I am not 100% sure that
this is the cause of the slow-down, but it certainly looks like
something is wrong here.
$ strace -o log python3 test.py
$ grep lseek log | wc -l
1871
$ strace -o log python3 -c 'print("Hello")'
Hello
$ grep lseek log | wc -l
31
-- System Information:
Debian Release: 8.1
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386
Kernel: Linux 3.16.0-4-amd64 (SMP w/8 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
Versions of packages python3-matplotlib depends on:
ii libc6 2.19-18
ii libfreetype62.5.2-3
ii libgcc1 1:4.9.2-10
ii libjs-jquery1.7.2+dfsg-3.2
ii libjs-jquery-ui 1.10.1+dfsg-1
ii libpng12-0 1.2.50-2+b2
ii libstdc++6 4.9.2-10
ii libtcl8.6 8.6.2+dfsg-2
ii libtk8.68.6.2-1
ii python-matplotlib-data 1.4.2-3.1
ii python3 3.4.2-2
ii python3-dateutil2.2-2
ii python3-nose1.3.4-1
ii python3-numpy [python3-numpy-abi9] 1:1.8.2-2
ii python3-pyparsing 2.0.3+dfsg1-1
ii python3-six 1.8.0-1
ii python3-tz 2012c+dfsg-0.1
Versions of packages python3-matplotlib recommends:
ii python3-pil 2.6.1-2
ii python3-tk 3.4.2-1+b1
Versions of packages python3-matplotlib suggests:
pn dvipng
ii ghostscript 9.06~dfsg-2+deb8u1
ii gir1.2-gtk-3.03.14.5-1
ii inkscape 0.48.5-3
ii ipython3 2.3.0-2
ii librsvg2-common 2.40.5-1
ii python-matplotlib-doc 1.4.2-3.1
pn python3-cairocffi
ii python3-gi [python3-gobject] 3.14.0-1
ii python3-gi-cairo 3.14.0-1
ii python3-pyq
