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
<nr...@trialphaenergy.com> 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
real 0m2.385s
user 0m2.312s
sys 0m0.064s
Freshly bootstrapped wheezy chroot:
$ time /usr/bin/python ./test.py
real 0m0.351s
user 0m0.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 got something interesting using the -c option. On Jessie:
$ strace -c /usr/bin/python2 test.py
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
76.89 0.000163 0 157839 4 lseek
14.15 0.000030 0 20349 read
4.72 0.000010 0 6114 4495 open
2.36 0.000005 0 11007 1087 stat
1.89 0.000004 0 3058 fstat
0.00 0.000000 0 48 write
0.00 0.000000 0 1763 close
0.00 0.000000 0 176 6 lstat
0.00 0.000000 0 112 poll
0.00 0.000000 0 1413 mmap
0.00 0.000000 0 147 mprotect
0.00 0.000000 0 1115 munmap
0.00 0.000000 0 165 brk
[...]
On Wheezy, on the other hand:
$ strace -c /usr/bin/python2 test.py
[...]
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00 0.000004 0 469 mmap
0.00 0.000000 0 1424 read
0.00 0.000000 0 9 write
0.00 0.000000 0 3924 3212 open
0.00 0.000000 0 714 close
0.00 0.000000 0 1223 997 stat
0.00 0.000000 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
