Bug#796905: python3-matplotlib: Matplotlib startup feels extremely slow

[Nikolaus Rath]

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\0000FFTMh\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

--