search

jyotisham / jyotisha

Python tools for the astronomical / astrological vedAnga of Hindus
MIT License
88 stars 53 forks source link

What makes code slower? #52

Closed vvasuki closed 4 years ago

vvasuki commented 4 years ago

Defining anga objects and specifying their algebra/ arithmetic would make things simpler - but would it be slower?

Command line in all of the below

pytest -k test_panchanga_chennai_18 --log-cli-level 0

For the anga obj branch:

FAILED                                                                   [100%]timebudget report...
            compute_angas: 83355.05ms for      1 calls
  update_festival_details: 40451.83ms for      2 calls
assign_festivals_from_rules: 35678.10ms for      2 calls
          assign_festival:    0.14ms for  500780 calls
assign_tithi_yoga_nakshatra_fest:    1.55ms for  43848 calls
                   __eq__:    0.00ms for  943794 calls
             dump_to_file:  590.65ms for      1 calls
           set_rule_dicts:  514.62ms for      1 calls
                   __lt__:    0.01ms for  37364 calls
                  __sub__:    0.00ms for  78473 calls
                  __add__:    0.00ms for  59969 calls
                   __gt__:    0.00ms for   5095 calls
timebudget report...

Takes 2 min 53 seconds = 173 seconds.

Master branch for comparison:

  update_festival_details: 6447.73ms for      2 calls
assign_festivals_from_rules: 3847.77ms for      2 calls
            compute_angas: 7575.29ms for      1 calls
          assign_festival:    0.01ms for  500780 calls
           set_rule_dicts:  513.87ms for      1 calls
             dump_to_file:  401.62ms for      1 calls
  assign_festival_numbers:    2.13ms for      2 calls
timebudget report...
         Loading the file:  847.15ms for      1 calls

Time taken without timebudget use : 21.x seconds, with timebudget: 23.x seconds

vvasuki commented 4 years ago

Master branch at f0ae81444f6de8f8122492052311603b0eec5b10:

[100%]timebudget report...
compute_angas: 79599.66ms for      1 calls
  get_sunrise_day_anga_spans:   39.17ms for   1910 calls
  find:   18.10ms for   4113 calls
update_festival_details: 12347.26ms for      2 calls
  assign_festivals_from_rules: 7671.97ms for      2 calls
  assign_festival:    0.03ms for  500780 calls
    set_rule_dicts:  568.00ms for      1 calls
      dump_to_file:  458.60ms for      1 calls
assign_festival_numbers:    2.14ms for      2 calls
  timebudget report...
Loading the file:  866.34ms for      1 calls

Total time: 48 seconds.

Master branch at 4cad977d6facc56eef9c4958c73f854ddaabe28b

PASSED                                                                   [100%]timebudget report...
update_festival_details: 6542.45ms for      2 calls
assign_festivals_from_rules: 3945.54ms for      2 calls
  compute_angas: 7429.03ms for      1 calls
assign_festival:    0.01ms for  500780 calls
  set_rule_dicts:  554.92ms for      1 calls
    dump_to_file:  399.63ms for      1 calls
assign_festival_numbers:    1.86ms for      2 calls
  timebudget report...
Loading the file:  859.72ms for      1 calls

Total time 23 seconds.

Analysis

These results recur consistently. Environment is the same: pycharm on intellij IDE. Computer details here.

What explains this ? There is no significant code change.

Perhaps this is an indication for us to abandon python (which is properly a fair prototyping language) in favor of something faster to run as well as to code - and perhaps even more porable. (Example: scala which is interoperable with java or go ). We shouldn't be wasting time worrying about whether some innocuous change will slowdown the code 10x. I will start looking at alternatives.

cc @karthikraman

vvasuki commented 4 years ago

https://github.com/sanskrit-coders/sanskrit_data/commit/c30e35fd517bf026f01cef6e66eefe7da1a85117 and https://github.com/sanskrit-coders/jyotisha/commit/2d46b3a46d24c8e36caf0e29553d0c7fce08fdae fix the problem!

Thanks to @shreevatsa for triggering this correction.

20s runtime now!

PASSED                                                                   [100%]timebudget report...
  update_festival_details: 5579.41ms for      2 calls
assign_festivals_from_rules: 3268.12ms for      2 calls
            compute_angas: 6344.11ms for      1 calls
          assign_festival:    0.01ms for  500780 calls
get_sunrise_day_anga_spans:    2.45ms for   1910 calls
                     find:    7.14ms for     89 calls
           set_rule_dicts:  575.89ms for      1 calls
             dump_to_file:  419.12ms for      1 calls
  assign_festival_numbers:    1.90ms for      2 calls
timebudget report...
         Loading the file:  826.86ms for      1 calls
shreevatsa commented 4 years ago

Was typing the following:

For what it's worth, though I couldn't get the tests to pass, I do see a slowdown in how long the test takes to fail at f0ae814 (about 30 seconds, versus 9.x seconds at previous commit). The minimal diff is this line: line 85 Removing that if block or even replacing that self.names_dict = NAMES[key] with self.names_dict = {} makes the difference go away.

I don't understand the rest of the code enough to know why, but my guess is that as this makes the AngaType object larger (about 6 times larger, 48 v/s 48+232), that causes something else to become slower.

BTW, in either case, most of the time of the test goes in sanskrit_data module. Some of the results from pprofile -m pytest -- -k "test_panchanga_chennai_18" (may not be the best choice of profiler; it has about 50x overhead and prints a lot of output):

At f0ae814:

File: /usr/local/lib/python3.8/site-packages/sanskrit_data-0.6.5-py3.8.egg/sanskrit_data/collection_helper.py
File duration: 738.809s (61.24%)
--
File: /usr/local/lib/python3.8/site-packages/sanskrit_data-0.6.5-py3.8.egg/sanskrit_data/schema/common.py
File duration: 368.833s (30.57%)
--
File: /Users/shreevatsa/code/jyotisha/jyotisha/panchaanga/temporal/body.py
File duration: 10.8639s (0.90%)
--

versus (without that NAMES[key]):

File: /usr/local/lib/python3.8/site-packages/sanskrit_data-0.6.5-py3.8.egg/sanskrit_data/collection_helper.py
File duration: 53.3035s (31.56%)
--
File: /usr/local/lib/python3.8/site-packages/sanskrit_data-0.6.5-py3.8.egg/sanskrit_data/schema/common.py
File duration: 25.2035s (14.92%)
--
File: /Users/shreevatsa/code/jyotisha/jyotisha/panchaanga/temporal/body.py
File duration: 9.47646s (5.61%)
--
vvasuki commented 4 years ago

The fix also clears up the angaobj branch.

About isinstance() calls

@shreevatsa 's very pertinent observation: "If I'm reading the image correctly, it says that isinstance took 16791 milliseconds in total, over 200882348 calls to it, so that's about 84 nanoseconds per call. I think that's reasonable (for Python anyway); probably the right conclusion is not that isinstance is slow but that it's being called too many times -- then one would have to see why (maybe in some places we can proceed under the assumption that we have the right type, or move the check to a caller where it will be called fewer times), etc. Many things in Python are indeed relatively slow, but often the slowness comes from the fact that Python makes certain things too easy and the straightforward way of writing code can end up with a lot of indirection, and become slow that way. "

An experiment in this vein:

Case 1

    try:
      return self.index == other.index
    except AttributeError:
      return self.index == other

Time taken: 35sec.

timebudget report...
            compute_angas: 20228.54ms for      1 calls
  update_festival_details: 5194.24ms for      2 calls
assign_festivals_from_rules: 2782.45ms for      2 calls
          assign_festival:    0.01ms for  500780 calls
assign_tithi_yoga_nakshatra_fest:    0.06ms for  43848 calls
                   __eq__:    0.00ms for  943794 calls
             dump_to_file:  622.63ms for      1 calls
           set_rule_dicts:  578.62ms for      1 calls
                  __sub__:    0.00ms for  78473 calls
                  __add__:    0.00ms for  59969 calls
                   __gt__:    0.00ms for   5095 calls
timebudget report...
         Loading the file:  863.30ms for      1 calls

Case 2

with:

    if isinstance(other, Number):
      return self.index == other
    return self.index == other.index

Time taken: 34sec.

FAILED                                                                   [100%]timebudget report...
            compute_angas: 19913.68ms for      1 calls
  update_festival_details: 5101.91ms for      2 calls
assign_festivals_from_rules: 2753.11ms for      2 calls
          assign_festival:    0.01ms for  500780 calls
assign_tithi_yoga_nakshatra_fest:    0.06ms for  43848 calls
                   __eq__:    0.00ms for  943794 calls
             dump_to_file:  633.30ms for      1 calls
           set_rule_dicts:  513.55ms for      1 calls
                  __sub__:    0.00ms for  78473 calls
                  __add__:    0.00ms for  59969 calls
                   __gt__:    0.00ms for   5095 calls
timebudget report...
         Loading the file:  856.03ms for      1 calls

Also the above shows that having anga objects increases time for anga computation from 6s to 20s. Will drop that idea.

vvasuki commented 4 years ago

Also the above shows that having anga objects increases time for anga computation from 6s to 20s. Will drop that idea.

Retracted considering https://github.com/sanskrit-coders/jyotisha/blob/6fb654442b745c0967f566e9702d52826b1ca9a6/tests/spatio_temporal/data/timing_snapshot_vvasuki.md vs https://github.com/sanskrit-coders/jyotisha/blob/master/tests/spatio_temporal/data/timing_snapshot_vvasuki.md . Inefficient daily anga span finding was the culprit.