Trying to run pystone -> StopIteration

[navytux]

Hello up there. I've tried to run CPython's pystone with Grumpy but instead of regular output it just prints "StopIteration" without any traceback. To try to see what is going on I've edded explicit try / traceback.print_exc() around main() and then it prints:

(grumpy) kirr@deco:~/src/tools/go/grumpy$ ./pystone
Traceback (most recent call last):
  File "pystone.py", line 275, in <module>
    main(loops)
  File "pystone.py", line 65, in main
    benchtime, stones = pystones(loops)
  File "pystone.py", line 72, in pystones
    return Proc0(loops)
  File "pystone.py", line 93, in Proc0
    starttime = clock()
  File "pystone.py", line 79, in <module>
    Array2Glob = map(lambda x: x[:], [Array1Glob]*51)
StopIteration

This looks strange as Array2Glob = map(lambda x: x[:], [Array1Glob]*51) is there in global context not inside some function but traceback shows it to be called from inside time.clock() (?).

Full source code for (a bit) adjusted pystone.py is here:

https://lab.nexedi.com/kirr/grumpy/blob/52625c82/pystone.py

Thanks beforehand,
Kirill

[trotterdylan]

Thanks for the bug report! I was able to reproduce the problem and fixed it in e97a8ec

Let me know if anything else comes up.

[navytux]

@trotterdylan thanks for fixing map and zip wrt StopIteration. Now running pystone under grumpy gives:

(grumpy) kirr@deco:~/src/tools/go/grumpy$ ./pystone
Traceback (most recent call last):
  File "pystone.py", line 275, in <module>
    main(loops)
  File "pystone.py", line 66, in main
    print "Pystone(%s) time for %d passes = %g" % \
NotImplementedError: conversion type not yet supported: g

If I change %g to %f it works. For the reference here are the results for Grumpy and CPython 2:

(grumpy) kirr@deco:~/src/tools/go/grumpy$ ./pystone     # grumpy
Pystone(1.1) time for 50000 passes = 0.745754
This machine benchmarks at 67046.258885 pystones/second

(grumpy) kirr@deco:~/src/tools/go/grumpy$ python2 ./pystone.py    # python 2.7.13
Pystone(1.1) time for 50000 passes = 0.215959
This machine benchmarks at 231525.606731 pystones/second

Thanks again,
Kirill

[cclauss]

@navytux Do you have pypy numbers too?

[navytux]

@cclauss yes:

(grumpy) kirr@deco:~/src/tools/go/grumpy$ pypy ./pystone.py 
Pystone(1.1) time for 50000 passes = 0.034607
This machine benchmarks at 1444797.178131 pystones/second

[trotterdylan]

Cool, if you want to file a new issue for the %g that'd be great.

Re: performance, fwiw my bet is that the bottleneck is the native calls to time(). Native calls currently use Go runtime reflection which is terribly slow. Long term I plan on exposing native objects statically at build time which should reduce the overhead substantially.

If you're interested in investigating performance you can produce Go profiles from Grumpy binaries using the GRUMPY_PROFILE environment variable. With that profile you can use the Go pprof tool as described here: https://blog.golang.org/profiling-go-programs

[navytux]

@trotterdylan thanks for feedback and GRUMPY_PROFILE hint. I've spawned %g to #306.

About time to run: the time() in pystone is called only to measure whole time - in the beginning and end, so it should not affect anything. Below is how actual profiling looks:

(grumpy) kirr@deco:~/src/tools/go/grumpy$ go tool pprof pystone cpu.out 
File: pystone
Type: cpu
Time: May 11, 2017 at 5:50pm (MSK)
Duration: 902.12ms, Total samples = 870ms (96.44%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 410ms, 47.13% of 870ms total
Showing top 10 nodes out of 130
      flat  flat%   sum%        cum   cum%
      90ms 10.34% 10.34%      110ms 12.64%  grumpy.Hash /home/kirr/src/tools/go/grumpy/build/src/grumpy/core.go
      60ms  6.90% 17.24%      150ms 17.24%  grumpy.(*dictTable).lookupEntry /home/kirr/src/tools/go/grumpy/build/src/grumpy/dict.go
      60ms  6.90% 24.14%      130ms 14.94%  runtime.mallocgc /home/kirr/src/tools/go/go/src/runtime/malloc.go
      50ms  5.75% 29.89%       50ms  5.75%  runtime.heapBitsForObject /home/kirr/src/tools/go/go/src/runtime/mbitmap.go
      30ms  3.45% 33.33%      100ms 11.49%  grumpy.Eq /home/kirr/src/tools/go/grumpy/build/src/grumpy/core.go
      30ms  3.45% 36.78%       30ms  3.45%  runtime.heapBitsSetType /home/kirr/src/tools/go/go/src/runtime/mbitmap.go
      30ms  3.45% 40.23%       50ms  5.75%  sync/atomic.StorePointer /home/kirr/src/tools/go/go/src/runtime/atomic_pointer.go
      20ms  2.30% 42.53%      790ms 90.80%  grumpy.(*Code).Eval /home/kirr/src/tools/go/grumpy/build/src/grumpy/code.go
      20ms  2.30% 44.83%       30ms  3.45%  grumpy.(*Code).Eval /home/kirr/src/tools/go/grumpy/build/src/grumpy/frame.go
      20ms  2.30% 47.13%       20ms  2.30%  grumpy.(*ParamSpec).Validate /home/kirr/src/tools/go/grumpy/build/src/grumpy/param.go

(https://lab.nexedi.com/kirr/misc/raw/6774d6d/grumpy/pprof001.svg)

to me offhand it looks like it is not reflections.

Good to know though there are plans to cut overhead for native calls.

Thanks again,
Kirill