strace of python shows nonsense

[Joep van Delft]

Hi there,


I am puzzled at how I borked my installation. Python loads slow on my
machine, and I decided to use strace and /usr/bin/time to see what is
actually happening.

# sync && echo 3 > /proc/sys/vm/drop_caches
$ /usr/bin/time python2 -c ""
0.19user 0.04system 0:01.22elapsed 19%CPU (0avgtext+0avgdata
4200maxresident)k
7312inputs+0outputs (4major+1145minor)pagefaults 0swaps

And when all is in memory:
$ /usr/bin/time python2 -c ""
0.19user 0.01system 0:00.21elapsed 98%CPU
(0avgtext+0avgdata 4216maxresident)k 0inputs+0outputs
(0major+1153minor)pagefaults 0swaps

$ /usr/bin/time python2 -c "import argparse"
0.36user 0.02system 0:00.39elapsed 98%CPU
(0avgtext+0avgdata 5752maxresident)k 0inputs+0outputs
(0major+1699minor)pagefaults 0swaps

..2 and .4 seconds to not even get started when all disk I/O is
cached. So what is happening here?

$ strace -c python2 -c ""
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
93.26 0.001910 8 230 168 open
3.66 0.000075 9 8 mprotect
3.08 0.000063 1 97 fstat64
0.00 0.000000 0 172 read
0.00 0.000000 0 63 close
<...>

$ strace -c python2 -c "import argparse"
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
51.89 0.003732 13 290 read
47.29 0.003401 18 192 155 stat64
0.82 0.000059 0 129 mmap2
0.00 0.000000 0 549 443 open
0.00 0.000000 0 107 close
<...>

What puzzles me, is the amount of errors for open and stat64. There
are references to stuff I don't know (~/GNUStep directory? Stuff
under site-packages that does not exist? Subdirs of site-packages
that are not included in sys.path?) What is python doing there, and
why? And, more importantly, how can this be corrected?

Probably irrelevant, but Python2 version 2.7.3, Archlinux (current as
of previous weekend).


Thanks,

Joep

 

[Steven D'Aprano]

Hi there,


I am puzzled at how I borked my installation. Python loads slow on my
machine, and I decided to use strace and /usr/bin/time to see what is
actually happening.

Before dropping down to such a low level, I suggest you start at a
higher, Python level.

Run `python -E` to disable any environment variables and startup file.
Does that help?

Compare sys.path when running with and without the -E switch. Any
important differences? Anything unusual in sys.path, such as directories
that don't exist?

Run `python -v` to print modules as they are loaded. (Warning: there are
a lot of them.) Can you see any obvious delays?


[...]

What puzzles me, is the amount of errors for open and stat64. There are
references to stuff I don't know (~/GNUStep directory? Stuff under
site-packages that does not exist? Subdirs of site-packages that are not
included in sys.path?) What is python doing there, and why? And, more
importantly, how can this be corrected?

What's the value of the environment variable PYTHONPATH?

Do you have a PYTHONSTARTUP set? What is in that file?

 

[Dieter Maurer]

...
What puzzles me, is the amount of errors for open and stat64.

The high number of errors comes from Python's import logic:
when Python should import a module/package (not yet imported),
it looks into each member on "sys.path" for about 6 different potential
filename spellings corresponding to the module -- until it succeeds
or has tried all members. Most such filesystem lookups will fail -
giving a high number of "stat" errors.