Page 1 of 1

Profiling Golly Scripts

Posted: December 17th, 2015, 8:16 pm
by Scorbie
Now that I learned how to profile Golly scripts instead of timing manually, I would like to share it here. Fortunately, Golly's profiling module cProfile works fine.
As you all know, launching a Golly script blocks stdout, so you have to print anything via g.show() which is quite inconvenient. Profiling is no exception, and just running cProfile.run(function()) would do nothing as it prints the information to stdout.

Here's my attempt on profiling A for Awesome's brand new hack on apgsearch:

Code: Select all

 ...Same as A for Awesome's verson...
def main(ruletype=ruletype):
    # Obtain the parameters to conduct the search:
    number = int(g.getstring("How many soups to search?", "5000000"))
   ....A lot of code....
    soup.display_unids()
    soup.display_census(scount, rootstring, symm, symmstring)

PROFILE = True
if PROFILE:
    import cProfile
    import pstats
    cProfile.runctx('main()', globals(), locals(), filename='apgprofile_dump')
    with open('apgprofile.txt', 'w') as profileresults:
        st = pstats.Stats('apgprofile_dump', stream=profileresults)
        st.sort_stats('tottime')
        st.print_stats()
else:
    main()
Basically, I wrapped all the global code to main() and ran cProfile. There were two caveats when I was working with the code:
1) A for Awesome's version of apgsearch used a global variable 'ruletype', so I had to use cProfile.runctx instead of cProfile.run. Also, for an unknown reason, just def main(): (which makes main access to the global variable) doesn't work. I had to tweak the code to def main(ruletype=ruletype): to make it work.
2) If Golly had allowed stdout, then life would have been much easier. A single cProfile.run(ctx) would have displayed the information nicely. It doesn't, so I had to dump the profile results to an external file 'apgprofile_dump' and (sort and) display it with pstats.

Any questions are welcome, but I suggest you first reading the profiler section of the Python docs and google it first.

EDIT: And here's how it looks like! apgprofile.txt (I only ran 200 soups cause it's soooo slow in my computer...)

Code: Select all

Fri Dec 18 09:01:24 2015    apgprofile_dump

         353559 function calls in 29.203 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      393    9.912    0.025    9.912    0.025 {golly.new}
        4    5.148    1.287    5.148    1.287 {golly.getstring}
    14684    2.906    0.000    2.906    0.000 {golly.run}
   128550    1.812    0.000    1.812    0.000 {golly.getcell}
      487    1.809    0.004    1.809    0.004 {golly.setrule}
      698    1.112    0.002    2.409    0.003 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:10932(gridobj)
      294    0.997    0.003    1.502    0.005 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:49(hashsoup)
     3232    0.861    0.000    1.793    0.001 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:238(canonise_orientation)
       89    0.674    0.008    0.674    0.008 {golly.step}
   105894    0.620    0.000    0.620    0.000 {method 'append' of 'list' objects}
      626    0.436    0.001    0.436    0.001 {golly.getcells}
    16405    0.362    0.000    0.362    0.000 {golly.getpop}
      137    0.272    0.002    2.291    0.017 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11042(naivestab)
      200    0.179    0.001    0.931    0.005 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11061(naivestab2)
     4178    0.147    0.000    0.147    0.000 {golly.hash}
     6029    0.143    0.000    0.143    0.000 {golly.setcell}
     3580    0.131    0.000    0.131    0.000 {golly.getrect}
      200    0.125    0.001    0.125    0.001 {golly.clear}
    17062    0.125    0.000    0.125    0.000 {max}
       94    0.118    0.001    0.118    0.001 {golly.store}
      394    0.099    0.000    0.099    0.000 {golly.setalgo}
        2    0.099    0.050   18.637    9.319 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11274(teenager)
     3232    0.096    0.000    0.163    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:273(compare_representations)
    12962    0.096    0.000    0.096    0.000 {min}
    15501    0.095    0.000    0.095    0.000 {len}
      390    0.080    0.000    2.065    0.005 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:209(canonise)
       23    0.077    0.003    0.077    0.003 {golly.fit}
        1    0.074    0.074    0.074    0.074 {golly.open}
      790    0.071    0.000    0.071    0.000 {golly.putcells}
      370    0.071    0.000   11.923    0.032 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11442(process_unid)
      390    0.064    0.000    0.423    0.001 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11168(bijoscar)
     9429    0.054    0.000    0.054    0.000 {ord}
      106    0.049    0.000    0.049    0.000 {golly.getdir}
        2    0.045    0.022   23.227   11.613 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11364(stabilise_soups_parallel)
       20    0.030    0.001    0.069    0.003 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:10895(grabobj)
       67    0.023    0.000    0.023    0.000 {golly.setbase}
      709    0.021    0.000    0.030    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:10795(awardpoints2)
      370    0.020    0.000    2.232    0.006 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11215(enter_unid)
        8    0.018    0.002    0.018    0.002 {golly.show}
      136    0.011    0.000    0.012    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:683(newvar)
      400    0.011    0.000    0.011    0.000 {golly.select}
     1480    0.011    0.000    0.011    0.000 {method 'pop' of 'list' objects}
       94    0.010    0.000    0.618    0.007 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11629(save_soup)
       17    0.009    0.001    1.111    0.065 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:464(pseudo_bangbang)
        1    0.008    0.008    0.008    0.008 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:614(setrule)
      719    0.008    0.000    0.008    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:10779(incobject)
      388    0.008    0.000    0.008    0.000 {_hashlib.openssl_sha256}
      200    0.006    0.000    3.228    0.016 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11090(stabilise3)
        1    0.006    0.006    0.700    0.700 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11649(display_census)
      412    0.006    0.000    0.006    0.000 {time.clock}
      709    0.004    0.000    0.004    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:10787(awardpoints)
      294    0.004    0.000    0.004    0.000 {method 'digest' of '_hashlib.HASH' objects}
       19    0.004    0.000    0.004    0.000 {golly.join}
       40    0.004    0.000    0.006    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:706(scoline)
      390    0.003    0.000    0.003    0.000 {abs}
       23    0.003    0.000    0.003    0.000 {golly.update}
      320    0.002    0.000    0.002    0.000 {chr}
       15    0.002    0.000    0.014    0.001 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:695(newvars)
        2    0.002    0.001    1.473    0.736 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:10826(census)
       30    0.002    0.000    0.002    0.000 {posix.stat}
       95    0.002    0.000    0.002    0.000 {method 'hexdigest' of '_hashlib.HASH' objects}
        1    0.001    0.001    0.012    0.012 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11550(save_progress)
       69    0.001    0.000    0.001    0.000 {golly.setstep}
        1    0.001    0.001   29.203   29.203 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11795(main)
        1    0.001    0.001    0.006    0.006 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:1517(saveContagiousLife)
       30    0.001    0.000    0.002    0.000 /usr/lib/python2.7/genericpath.py:15(exists)
       10    0.001    0.000    0.047    0.005 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:658(saverule)
        1    0.001    0.001    0.056    0.056 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:1165(saveClassifyObjects)
        3    0.000    0.000    0.000    0.000 {open}
        3    0.000    0.000    0.000    0.000 {method 'close' of 'file' objects}
        4    0.000    0.000    0.000    0.000 {sorted}
        3    0.000    0.000    0.000    0.000 {method 'write' of 'file' objects}
        1    0.000    0.000    0.003    0.003 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:1054(saveCoalesceObjects)
        1    0.000    0.000    0.068    0.068 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:600(saveAllRules)
        1    0.000    0.000    0.031    0.031 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11528(display_unids)
        8    0.000    0.000    0.000    0.000 {range}
        6    0.000    0.000    0.000    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:11780(ord2)
        1    0.000    0.000    0.000    0.000 {built-in method now}
        2    0.000    0.000    0.000    0.000 {golly.getevent}
        1    0.000    0.000    0.000    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:135(check)
        1    0.000    0.000    0.002    0.002 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:987(saveExpungeObjects)
        1    0.000    0.000    0.001    0.001 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:1459(savePropagateClassifications)
        4    0.000    0.000    0.000    0.000 {method 'iteritems' of 'dict' objects}
        4    0.000    0.000    0.000    0.000 {method 'copy' of 'dict' objects}
        1    0.000    0.000   29.203   29.203 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {_hashlib.openssl_md5}
        2    0.000    0.000    0.000    0.000 {method 'startswith' of 'str' objects}
        1    0.000    0.000    0.000    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:907(saveEradicateInfection)
        1    0.000    0.000    0.000    0.000 {method 'isoformat' of 'datetime.datetime' objects}
        1    0.000    0.000    0.000    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:782(saveExpungeGliders)
        2    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}
        1    0.000    0.000    0.000    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:945(savePercolateInfection)
        1    0.000    0.000    0.000    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:827(saveIdentifyGliders)
        1    0.000    0.000    0.000    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:722(saveHandlePlumes)
        1    0.000    0.000    0.000    0.000 {math.sqrt}
        1    0.000    0.000    0.000    0.000 /home/scorbie/Apps/golly/Scripts/Perl/apgsearch-2015-12-17-v0.54+0.1i.py:158(convert)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Re: Profiling Golly Scripts

Posted: December 17th, 2015, 9:38 pm
by Andrew
Scorbie wrote:As you all know, launching a Golly script blocks stdout ...
I don't think that's correct, at least not on my Mac. I can add print calls or sys.stdout.write() calls to a Golly script and the output appears in the Console app. On Linux, if you start golly from a terminal shell I'd imagine the output would appear in the terminal. No idea what happens on Windows.

I used this bit of code to flush the output after every print/sys.stdout.write call (for some reason sys.stdout.flush didn't seem to do anything):

Code: Select all

import sys
import os
sys.stdout = os.fdopen(sys.stdout.fileno(), 'w', 0)
Golly *does* capture stderr output, so it can display any error messages in a nice dialog box. It does this via this bit of code in the InitPython routine in wxpython.cpp:

Code: Select all

        // catch Python messages sent to stderr and pass them to py_stderr
        if ( PyRun_SimpleString(
                                "import golly\n"
                                "import sys\n"
                                "class StderrCatcher:\n"
                                "   def __init__(self):\n"
                                "      self.data = ''\n"
                                "   def write(self, stuff):\n"
                                "      self.data += stuff\n"
                                "      golly.stderr(self.data)\n"
                                "sys.stderr = StderrCatcher()\n"
                                
                                // also create dummy sys.argv so scripts can import Tkinter
                                "sys.argv = ['golly-app']\n"
                                // works, but Golly's menus get permanently changed on Mac
                                ) < 0
            ) Warning(_("StderrCatcher code failed!"));
If you have problems seeing stdout messages (say, on Windows) you could probably write a similar StdoutCatcher class to capture the messages in a file or string or whatever.

Re: Profiling Golly Scripts

Posted: December 18th, 2015, 7:02 am
by Scorbie
Andrew wrote:
Scorbie wrote:As you all know, launching a Golly script blocks stdout ...
I don't think that's correct, at least not on my Mac. I can add print calls or sys.stdout.write() calls to a Golly script and the output appears in the Console app. On Linux, if you start golly from a terminal shell I'd imagine the output would appear in the terminal. No idea what happens on Windows.
Image
Achkcqhkqhcqhkkkkk! That one's shocking! Launching from the Terminal! Why didn't I think of that! On Linux it works just as you said. Thanks a lot, Andrew!
A related feature: One can print debug information to STDOUT, and the end users (launching golly by clicking) would not see a thing.
It's kinda :oops: that I may be the only one who didn't know this!

Re: Profiling Golly Scripts

Posted: July 4th, 2016, 11:38 am
by Scorbie
I know I said this before, but if anyone got profiling lua golly scripts to work, please let me know here. Thanks!