[pypy-issue] [issue1486] Pypy disk IO is slower than python2.6？

[Yaroslav Fedevych]

Yaroslav Fedevych <jaroslaw.fedewicz at gmail.com> added the comment:

Can't help but notice two things:

0) close is missing parentheses — which in my case leads to too many open files
on PyPy (due to GC differences, of course), but could be, say, swapping the
cause of slowdown? The file objects just sit there waiting to be collected...

1) can't be the difference due to the JIT warmup? A test case that gives more
work (like recursively reading all user-accessible files starting at /) would be
a bit more convincing...

2) I tried to run the attached test case on recent PyPy build and noticed that
profile is giving funny results:

bigbuddy:~ jafd$ time pypy -mprofile test.py 
         17221 function calls in 1086664311533356.250 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      867 -45897692753392.812 -52938515286.497 -45897692753392.812
-52938515286.497 :0(__new__)
      867 -30272791276041.523 -34916714274.558 -30272791276041.523
-34916714274.558 :0(__setattr__)
      836 2115208175656.440 2530153320.163 2115208175656.440 2530153320.163
:0(close)
     1703 -39838690480920.453 -23393241621.210 -39838690480920.453
-23393241621.210 :0(endswith)
     1734 -54779616801475.984 -31591474510.655 -54779616801475.984
-31591474510.655 :0(len)
        1 -549755.812 -549755.812 -549755.812 -549755.812 :0(listdir)
        1    0.002    0.002    0.002    0.002 :0(setprofile)
     1703 -42086944674548.781 -24713414371.432 -42086944674548.781
-24713414371.432 :0(startswith)
      867 2335352521858491.500 2693601524634.938 1843735061872581.500
2126568698814.973 :0(stat)
     3468 -145999709112752.812 -42099108740.701 -145999709112752.812
-42099108740.701 _structseq.py:22(__get__)
      867 -260203318219848.438 -300119167496.942 -391153419050758.750
-451157346079.307 _structseq.py:70(structseq_new)
      867 -171200198957734.906 -197462743895.888 1475320231703065.000
1701638098850.133 genericpath.py:26(isfile)
     1703 -173595051423241.812 -101934851099.966 -255520686578711.094
-150041507092.608 posixpath.py:60(join)
        1    0.001    0.001 1086664311533435.375 1086664311533435.375
profile:0(<code object <module>, file 'test.py', line 1>)
        0    0.000             0.000          profile:0(profiler)
      867 -33930050370621.383 -39135006194.488 -33930050370621.383
-39135006194.488 stat.py:24(S_IFMT)
      867 -117748912663560.141 -135811894652.318 -151678963034181.531
-174946900846.807 stat.py:49(S_ISREG)
        1    0.001    0.001 1086664311533435.375 1086664311533435.375
test.py:1(<module>)
        1 -135250441216896.922 -135250441216896.922 1086664311533435.375
1086664311533435.375 test.py:3(main)



real	0m5.250s
user	0m4.717s
sys	0m0.470s

profile here is terribly wrong, as shown by time command output and the fact
that I was able to see the script start and finish in my lifetime.

Not sure if this profile.py timing should be split to a bug of its own.

----------
nosy: +jafd

________________________________________
PyPy bug tracker <tracker at bugs.pypy.org>
<https://bugs.pypy.org/issue1486>
________________________________________