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