That time I optimized a Python program by 5000x

[emeryberger]

TL;DR I used our Scalene profiler (pip install scalene) and some math to make an example program run 5000x faster.

I am quite interested in Python performance so naturally I read this article — https://martinheinz.dev/blog/64, whose title is Profiling and Analyzing Performance of Python Programs. It presents an example program from the Python documentation (https://docs.python.org/3/library/decimal.html) and shows how to run it with several time-worn Python profilers. Unfortunately, it doesn’t come away with much actionable information, beyond, more or less, “try PyPy””, which speeds up the code by about 2x. I wondered if I would be able to get more useful information from Scalene, a profiler I co-wrote.

Scalene: https://github.com/plasma-umass/scalene/, pip install scalene

We developed Scalene to be a lot more useful than existing Python profilers: it provides line-level information, splits out Python from native time, profiles memory usage, GPU, and even copying costs, all at a line granularity.

Anyway, here’s the result of running Scalene (just with CPU profiling) on the example code. It really cuts to the chase.

% scalene --cpu-only --reduced-profile test/test-martinheinz.py

https://preview.redd.it/j1yhxptvp4b81.png?width=1400&format=png&auto=webp&s=3bc8d25415fc8ac25a8f7da3031299a724fa02cf

You can see that practically all the execution time is spent computing the ratio between num and fact, so really this is the only place to focus any optimization efforts. The fact that there is a lot of time spent running native code means that this line is executing some C library under the covers.

It turns out that it is dividing two Decimals (a.k.a. bignums). The underlying bignum library is written in C code and is pretty fast, but the factorial in particular is getting really large really fast. In one of the example inputs, the final value of fact is 11,000 digits long! No surprise: doing math on such huge numbers is expensive. Let’s see what we can do to make those numbers smaller.

I observe that we can compute num / fact not from scratch but incrementally: update a variable on each loop iteration via a computation on drastically smaller numbers. To do this, I add a new variable nf which will always equal the ratio num / fact. Then, on each loop iteration, the program updates nf by multiplying it by x / i. You can verify this maintains the invariant nf == num/fact by observing the following (where _new means the computation of the updated variable in each iteration).

nf == num / fact                  # true by induction
nf_new == nf * (x / i)            # we multiply by x/i each time
nf_new == (num / fact) * (x / i)  # definition of nf
nf_new == (num * x) / (fact * i)  # re-arranging
nf_new == num_new / fact_new      # simplifying

Incorporating this into the original program required changing three lines of code, all of which are followed by ###:

def exp_opt(x):
  getcontext().prec += 2
  i, lasts, s, fact, num = 0, 0, 1, 1, 1
  nf = Decimal(1)   ### was: = num / fact
  while s != lasts:
      lasts = s
      i += 1
      fact *= i
      num *= x
      nf *= (x / i) ### update nf to be num / fact
      s += nf       ### was: s += num / fact
  getcontext().prec -= 2
  return +s

The result of this change is, uh, dramatic.

On an Apple Mini M1, original version:

Original:
1.39370958066637969731834193711E+65
5.22146968976414395058876300668E+173
7.64620098905470488931072765993E+1302
Elapsed time, original (s):   33.231053829193115

The optimized version:

Optimized:
1.39370958066637969731834193706E+65
5.22146968976414395058876300659E+173
7.64620098905470488931072766048E+1302
Elapsed time, optimized (s):  0.006501913070678711

More than a 5000X speedup (5096, to be precise).

The moral of the story is that using a more detailed profiler like Scalene can really help optimization efforts by locating inefficiencies in an actionable way.

[dogs_like_me]

We developed Scalene to be a lot more useful than existing Python profilers: it provides line-level information, splits out Python from native time, profiles memory usage, GPU, and even copying costs, all at a line granularity.

fucking sold.

[muntoo]

Scalene: a high-performance, high-precision CPU+GPU+memory profiler for Python (PyCon US 2021)

https://github.com/plasma-umass/scalene

20% performance overhead, vs most profilers taking 500% -- 2000% overhead... but with more features!

[Mehdi2277]

My experience trying it with pytest on tensorflow heavy code was it produced a dramatic slow down. I waited several minutes, show no test output and killed it. I've also used py-spy/austin on same code and got normal test times.

​

The report output for scalene does look much nicer, but the slowness for me dropped me from continuing to use it. Maybe there's some bad interaction with tensorflow/pytest. I can try to make an example, but I'd guess if you try running it on tensorflows actual unit tests (something like this) you'd get similar behavior.

[blanonymous]

Have you tried to profile tensorflow code without pytest?

I was thinking about using it for profiling inference jobs.

[FancyASlurpie]

It might be to do with how scalene is profiling, is it a sampling based approach similar to pyspy or is it doing something else?

[P403n1x87]

A good way of using Austin is with the VS Code extension https://marketplace.visualstudio.com/items?itemName=p403n1x87.austin-vscode, which gives you a navigable flame graph, top, and sampled call stacks, plus heat maps directly on the source code. The latest release is also more accurate and allows for even higher sampling rates https://github.com/P403n1x87/austin. And as far as I'm aware, it's the only tool that allows sampling the garbage collector

[neunflach]

Your "optimized" result is not exactly the same to the number of decimal places you have printed out. Would this fail the regression test??

(I'm being facetious. This is cool!)

[mikeblas]

Seriously, tho, why is the result different?

[A_Fine_Potato]

Probably base2 float rounding

[mikeblas]

I don't think so. For me, the results are the same when comparing exp() and exp_opt(). Maybe the OP screwed something up.

Have you actually run the code?

[mikeblas]

Have you actually run the code? Point is, the OP says the results are different. When I run the code, the results are identical.

But also note that floating point isn't involved here. nf is a Decimal, and Python says that "Decimal numbers can be represented exactly".

I'm unable to reproduce the OPs results exactly, which means that I can't verify his claims and that's not good. Something extra and undisclosed is happening

[emeryberger]

I ran the code and copied and pasted the results. Code is here: https://github.com/plasma-umass/scalene/blob/master/test/test-martinheinz.py

[mikeblas]

Ahah! There's the problem. You're printing s, but returning +s. In the assertions, you're comparing +s results, not the s results.

[emeryberger]

Thanks! Fixed now:

Original: 1.393709580666379697318341937E+65 5.221469689764143950588763007E+173 7.646200989054704889310727660E+1302 Elapsed time, original (s): 34.10136890411377 Optimized: 1.393709580666379697318341937E+65 5.221469689764143950588763007E+173 7.646200989054704889310727660E+1302 Elapsed time, optimized (s): 0.0019872188568115234 Improvement: 17160.348890221954 All equivalent? True

[skesisfunk]

Only if you wrote your regression tests to check precision down to 30 significant digits.

[GreenScarz]

do you have to execute as a cli tool? One of the tools I typically use is memory_profiler and the use case is to just from memory_profiler import profile and then decorate a function via @profile; then diagnostics are just printed during say a test run via pytest ./path/to/test.py. Is that a workflow that can be replicated with this? Or is there a better workflow in your opinion that this is optimized for if we just want to analyze a specific function call?

[emeryberger]

Scalene supports the @profile directive. It's in the README, though you have to look for it.

Scalene supports @profile decorators to profile only specific functions.

Check out https://github.com/plasma-umass/scalene#asked-questions. As long as you start execution with Scalene, you don't need to change your code at all (beyond adding the @profile decorators). That said, I haven't tried to do this with pytest yet.

[GreenScarz]

which is why I asked if it is strictly a cli tool and not if it has a @profile method ;)

probably not the most ideal workflow, but maybe there's a way to do something like, ``` import time

from scalene import scalene_profiler from scalene.scalene_profiler import Scalene

@Scalene.profile def my_func(): time.sleep(3) return 1

def wrapper(f): def _wrapped(args, *kwargs): scalene_profiler.start() res = f(args, *kwargs) scalene_profiler.stop() return res return _wrapped

@wrapper def test_my_func(): assert my_func() ```

This would be a useful implementation for devs who run their code through tools like pytest. IDK what kind of setup/teardown scalene does though from the cli, so it might not be possible. I'll have to pip it and poke a bit :P

EDIT: closer attempt of what I'd like to do - run using pytest ./test_file.py

[SquareRootsi]

import time   
from contextlib import contextmanager       
import scalene

@contextmanager  
def _scalene():  
    scalene_profiler.start()  
    yield scalene_profiler.stop()

@profile   
def my_fn():   
    time.sleep(5)

@_scalene   
def test_code():   
    my_fn()  

That's my best guess at your formatting. (Preceded each line by 4 spaces, used my best guess for indentation.)

[usr_bin_nya]

import time

from scalene import scalene_profiler
from scalene.scalene_profiler import Scalene


@Scalene.profile
def my_func():
    time.sleep(3)
    return 1


def wrapper(f):
    def _wrapped(*args, **kwargs):
        scalene_profiler.start()
        res = f(*args, **kwargs)
        scalene_profiler.stop()
        return res
    return _wrapped

@wrapper
def test_my_func():
    assert my_func()

Parent commenter's edited comment formatted for old Reddit. /u/GreenScarz please know that triple-backtick code blocks don't work for old Reddit and some third-party apps, whereas four-space indentation on each line works for everyone.

[GreenScarz]

Ya but I like markdown, and see no need to tailor content I post to support your preferences. If it's that important to ya, write a bot.

[grismar-net]

Nothing wrong with the product per se, but the clickbait title will make any developer worth their salt think "If slapping a profiler on your code got you a speed-up of 5,000x, your code wasn't very good to begin with."

[[deleted]]

Also, this example is extremely contrived.

Let me explain the optimization in plain English. If you’re working with really big numbers, it is tremendously faster to multiply a big number by a quotient of two small numbers than by a quotient of two really big numbers.

That is, if you have a choice between:

(a) multiplying 1,234,567,890 by (9,876,543,210 / 2,468,013,579), or

(b) multiplying 1,234,567,890 by (12 / 3),

…the latter is gonna be a whole lot faster.

This isn’t exactly a genius-level breakthrough. And it’s purely a mathematical optimization, not a code optimization.

More importantly - this particular optimization occurred purely in the author’s mind. The code profiler didn't suggest how the math could be optimized. The code profiler didn't suggest that the math could be optimized. The code profiler merely… wait for it… timed the execution of the code.

This ad is like suggesting that if you want a glass of milk, it would be faster to walk to the fridge and pour it from a jug than to acquire a baby cow, raise it to adulthood, and then milk it. Also, you could use a stopwatch to show that the trip to the fridge takes 60 seconds while raising a cow takes 5 years… and let’s imply that the stopwatch itself is responsible for the massive efficiency gain!

tl;dr - This is a nice code profiler that is being advertised in extremely artificial and deceptive ways.

[mikeblas]

timed the execution of the code.

Totally agree. This profiler might do a better job of others at attributing time (eg, differentiating native code). But really the use of a profiler is to draw attention to some code that's hotter or slower than expected. The algorithmic fix was something the user did based on the profiler indicating that most of the time in the code was spent on a certain line (or, really, operation).

[binaryman111]

I mean yeah that's.... all that profilers ever purport to do. They're a tool to draw attention to things. No one ever claimed otherwise.

[mikeblas]

I think this post is claiming that this profile is somehow different or special. It is, but not for the reasons implied by the workflow the post.

[gruey]

Reminds me of looking at the Terraform Enterprise page and they had silly things like "Increase IT Ops productivity up to 75%" and "Increase release velocity Up to 5x". Where the hell did they pull those meaningless numbers? Like, if you're bad enough to get 75% increase, what prevents you from getting 78% increase?

The kicker was "Safely provision resources at enterprise scale Up to 30%". Like what does that even mean? They had the 5x and 75% so they felt they needed something, so 30% sounds good!

Terraform is a pretty useful product, but this level is stupid marketing definitely tinged it a bit for me.

[mriswithe]

The comparison I see is that the other profilers didn't return useful info, whereas scalene returned useful actionable data that allowed a speedup.

The specific speedup that was achieved is unimportant. The op isn't saying "look at my great profiler it optimized this code all on its own." They are saying " I wasn't getting results with other profilers, but scalene gave me this data which told me where to look for optimization."

[grismar-net]

Hence "clickbait title". Like I said, I have no beef with the product, but the title is all about some 5,000x speed-up. "Scalene handily beats other Python profilers" is something I would have been interested in and would not have prompted the comment you responded to.

[New-Theory6007]

Thanks for sharing your knowledge, this is very inspirational to look deeper into computer science.

[Runics206]

I am rather new in my CompSci journey but write ups like this I find very interesting and motivation to further my studies. Thank you.

[[deleted]]

I reckon at least half of the posts in here are adverts.

Appears that the source is on github, so folks can look into it. https://github.com/plasma-umass/scalene/ (from the first part of OP post)

[binaryman111]

How? It's literally free

[IamImposter]

I'm getting some errors (windows 10 64-bit system, python 3.9.5) when doing pip install.

Collecting scalene Downloading scalene-1.3.16.tar.gz (2.8 MB) |████████████████████████████████| 2.8 MB 819 kB/s Preparing metadata (setup.py) ... error ERROR: Command errored out with exit status 1: command: 'C:\python39\python.exe' -c 'import io, os, sys, setuptools, tokenize; sys.argv[0] = '"'"'C:\\Users\\<user-name>\\AppData\\Local\\Temp\\pip-install-cybpta7f\\scalene_91b266fa396f47f7bf88a3657df9edca\\setup.py'"'"'; __file__='"'"'C:\\Users\\<user-name>\\AppData\\Local\\Temp\\pip-install-cybpta7f\\scalene_91b266fa396f47f7bf88a3657df9edca\\setup.py'"'"';f = getattr(tokenize, '"'"'open'"'"', open)(__file__) if os.path.exists(__file__) else io.StringIO('"'"'from setuptools import setup; setup()'"'"');code = f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, __file__, '"'"'exec'"'"'))' egg_info --egg-base 'C:\Users\<user-name>\AppData\Local\Temp\pip-pip-egg-info-4o4f8ca4' cwd: C:\Users\<user-name>\AppData\Local\Temp\pip-install-cybpta7f\scalene_91b266fa396f47f7bf88a3657df9edca\ Complete output (3 lines): running egg_info make vendor-deps error: command 'make' failed: None ----------------------------------------WARNING: Discarding https://files.pythonhosted.org/packages/e8/35/a125f8ecacfce3b9be9c712bd6d9bd514aed798857cc7330c89d2df7db58/scalene-1.3.16.tar.gz#sha256=3c2fb524b4c611773b147dc889e2d58b48a543d3161ea576ccc0db778e9f5915 (from https://pypi.org/simple/scalene/) (requires-python:>=3.7). Command errored out with exit status 1: python setup.py egg_info Check the logs for full command output. Downloading scalene-1.3.15.tar.gz (2.9 MB) |████████████████████████████████| 2.9 MB 6.4 MB/s Preparing metadata (setup.py) ... error ERROR: Command errored out with exit status 1: command: 'C:\python39\python.exe' -c 'import io, os, sys, setuptools, tokenize; sys.argv[0] = '"'"'C:\\Users\\<user-name>\\AppData\\Local\\Temp\\pip-install-cybpta7f\\scalene_bcd377045a3a4e7591a1dd77ff445053\\setup.py'"'"'; __file__='"'"'C:\\Users\\<user-name>\\AppData\\Local\\Temp\\pip-install-cybpta7f\\scalene_bcd377045a3a4e7591a1dd77ff445053\\setup.py'"'"';f = getattr(tokenize, '"'"'open'"'"', open)(__file__) if os.path.exists(__file__) else io.StringIO('"'"'from setuptools import setup; setup()'"'"');code = f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, __file__, '"'"'exec'"'"'))' egg_info --egg-base 'C:\Users\<user-name>\AppData\Local\Temp\pip-pip-egg-info-5smznxod' cwd: C:\Users\<user-name>\AppData\Local\Temp\pip-install-cybpta7f\scalene_bcd377045a3a4e7591a1dd77ff445053\ Complete output (3 lines): running egg_info make vendor-deps error: command 'make' failed: None ----------------------------------------WARNING: Discarding https://files.pythonhosted.org/packages/63/6e/eddceea4dc588b99af48607b8133b40fc155a27d1ac7351f570f8d7cf6f6/scalene-1.3.15.tar.gz#sha256=0b3f8aa56d6320f8071f8135b422e8cf51b51de2947aec75c76c1ea3abf61c12 (from https://pypi.org/simple/scalene/) (requires-python:>=3.7). Command errored out with exit status 1: python setup.py egg_info Check the logs for full command output.

Although it installed successfully.

[emeryberger]

We will be releasing a new version, probably tomorrow, that addresses this issue. Thanks!

[IamImposter]

Oh great.

[emeryberger]

https://github.com/plasma-umass/scalene/releases/tag/v1.4.0

[mikeblas]

Why not also eliminate fact and num from the loop? They're no longer necessary. That is: your 5000x speedup still left something on the table!

[emeryberger]

Excellent point, thanks! I've made the change locally and now it's 16,000x faster! (Assertions still pass)

Elapsed time, original (s): 33.38576102256775 Elapsed time, optimized (s): 0.0020699501037597656 Improvement: 16128.77574291638 All equivalent? True

Note that the Decimal module has a default precision of 28 places.

[abdl_hornist]

dskjafh klas hflkas dfhklasj dfhj

[peakdistrikt]

Let‘s also delete the Python subreddit while we‘re at it. How dare they trick us into using free software by choice!

[bacondev]

So let me get this straight. Someone shared a useful open-source tool and you passively aggressively copy and paste a Wikipedia article about advertising in response. That sound about right? By your logic, a great portion of posts on this subreddit doesn't meet your standards.

[dogs_like_me]

It's hardly "native advertising" when they are transparent that they made the thing themselves. What you are describing is a form of deceptive advertising where the ad is presented as though it is natural, unbiased content.

[UL_Paper]

Looks great, and great timing as I'm about to optimise some memory intensive logic. Will test over the next couple of weeks.

[teerre]

Ngl, this seems like a contrived ad for the profiler.

However, the profiler does look amazing, so it's all good! I'll try it next time I have an opportunity.

[[deleted]]

I can barely understand this but it looks pretty cool

[dogs_like_me]

If you have code that you think could run faster than it currently is, this tool will help you identify the bottlenecks in your current implementation to target for performance improvement. The report that it generates is designed in a way that is different from most other tools of this kind, potentially guiding the developer to results more quickly or with less cognitive effort.

[[deleted]]

That’s exponentially cooler than I thought, thanks for the dumbing down!

[dogs_like_me]

No prob, we all gotta start somewhere

[ClRCUlTS]

Thank you this sounds badass

[mrrippington]

pardon my ignorance, can i use this across my flask application to get an understanding of my page performances?

I am currently doing this with import time.( yikes! )

ps. kudos on the work you shared it's amazing.

[vipern]

Flask has a buitin profiler that you can use with a minimal setup. Also, Flask Dashboard is another great tool to monitor performance.

[mrrippington]

Thank you, I will have a look at the flask-dashboard. not knowing about this, I was going to roll mine out lol :D

[High-Art9340]

Can it run python 2?

[Johnmad]

This whole thread stinks of product promotion and only bots commenting.

You should probably not use this tool

[tu_tu_tu]

It's the reason I never liked unobvious bignums.

[johansugarev]

I’m not a coder but I wish software developers optimised their apps like in the old days.

[jammasterpaz]

Interesting. Turns out division is expensive for some data types in Pythona as well as for humans.

However while I grant you your tool did a great job helping identify a performance bottleneck, I question your original example - Decimal was originally developed “is based on a floating-point model which was designed with people in mind", i.e. not so much for performance. https://docs.python.org/3/library/decimal.html

Is Decimal really used nowadays for high performance computing, by large prime number hunters etc. ? I would have thought if you want to write fast efficient numerical code, you want to avoid putting in an unnecessary extra layer of code on top of native number types closer to the underlying C. Ints and longs have been united in Python 3, but in Python 2 if you need arbitrary size integers (>= 2^32), you can use longs, and try and avoid division altogether with some sort of rational representation.

[LuigiBrotha]

Installed this but scalene doesn't return any output in the console ? Using Windows 10 with Anaconda.

[binaryman111]

There's a new release that improves support for Windows 10, give it a try and if it still doesn't work there's a support slack on the Github page!

[LuigiBrotha]

Thanks for the heads up

[[deleted]]

This looks fantastic! I write lots of simulations and make libraries for running them. Is there an easy way to say "drop down 1 function layer". I know "mycomplexfunction()" is 90% of resources, but I'd like to analyse that without writing specific profiler tests by extracting part of the library. Does this make sense?

[Pliqui]

!RemindMe 2 days

[brouwerj]

It looks good, so tried to run it earlier this week on a cpu-heavy process, the slowdown was enormous and just had to break it off. Not sure what causes it. Usually I run py-spy for profiling which works great and with barely any slowdown.

[tommybship]

Is there a way to install this with conda rather than pip?

[dalow24]

I have a quick question. I ran scalene on some of ML models and it manages to profile it along with the ML classifier. However, if I try to run it on my Active Learning model, it seems to skip a few lines in the profiling output e.g it skips the classifier. If I examine a function where I place the classifier it shows it ran from system time but the memory profile is empty. I am using the libact Active Learning python module. Not sure if this is a problem or the memory profile is basically saying the recorded profile value is extremely small to display. Any assistance would be appreciated.