#797918 python3-matplotlib: Matplotlib startup feels extremely slow

Package:
python3-matplotlib
Source:
matplotlib
Description:
Python based plotting system in a style similar to Matlab (Python 3)
Submitter:
Nikolaus Rath
Date:
2015-09-03 18:24:04 UTC
Severity:
normal
#797918#5
Date:
2015-08-24 21:12:17 UTC
From:
To:
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\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.

$ 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