R1D2 Profiling Python

| programming | python |

I spent some time fiddling with Lambda. The code now more or less works.

Moving on to optimization, I started reading about profiling in python.

I’ve been using time to see how long the script takes to run. Using cProfile allows you to see how long each specific method call in your application takes to run. Running this on old_posts.py produced the following output.

The following command executes the script under profiling, sorts the results by time and saves the output to a text file.

python -m cProfile -s time old_posts.py > profile.txt
Results (truncated to top results, since there were many calls being made that took a non-significant amount of time) 
289508 function calls (286008 primitive calls) in 6.616 seconds

Ordered by: internal time


ncalls  tottime  percall  cumtime  percall filename:lineno(function)
284    5.495    0.019    5.495    0.019 {method ‘read’ of ‘_ssl._SSLSocket’ objects}
24    0.514    0.021    0.514    0.021 {method ‘do_handshake’ of ‘_ssl._SSLSocket’ objects}
24    0.157    0.007    0.157    0.007 {method ‘connect’ of ‘_socket.socket’ objects}
24    0.123    0.005    0.123    0.005 {method ’load_verify_locations’ of ‘_ssl._SSLContext’ objects}
24    0.027    0.001    0.030    0.001 connectionpool.py:410(close)
24    0.015    0.001    0.015    0.001 {built-in method _socket.gethostbyname}
173    0.015    0.000    0.015    0.000 {built-in method marshal.loads}
22    0.013    0.001    0.013    0.001 decoder.py:345(raw_decode)
24    0.012    0.001    0.013    0.001 {built-in method _socket.getaddrinfo}
20    0.012    0.001    0.012    0.001 {built-in method _imp.create_dynamic}
486/483    0.009    0.000    0.017    0.000 {built-in method builtins.build_class}
1019    0.007    0.000    0.007    0.000 {built-in method posix.stat}
24    0.007    0.000    0.007    0.000 {built-in method _scproxy._get_proxy_settings}
189/1    0.005    0.000    6.616    6.616 {built-in method builtins.exec}
2472    0.005    0.000    0.008    0.000 parser.py:68(get_token)
1    0.004    0.004    0.004    0.004 {method ‘read’ of ‘_io.TextIOWrapper’ objects}
266/80    0.003    0.000    0.010    0.000 sre_parse.py:470(_parse)
206    0.003    0.000    0.023    0.000 parser.py:622(_parse)
460    0.003    0.000    0.015    0.000 <frozen importlib._bootstrap_external>:1233(find_spec)
14107    0.003    0.000    0.005    0.000 {built-in method builtins.isinstance}
601    0.003    0.000    0.003    0.000 {built-in method new of type object at 0x107136800}
173    0.003    0.000    0.004    0.000 <frozen importlib._bootstrap_external>:830(get_data)
24    0.003    0.000    0.003    0.000 {built-in method _scproxy._get_proxies}
24068/23811    0.002    0.000    0.004    0.000 {built-in method builtins.len}
3615    0.002    0.000    0.007    0.000 os.py:664(getitem)
3936    0.002    0.000    0.011    0.000 _collections_abc.py:742(iter)
495/71    0.002    0.000    0.010    0.000 sre_compile.py:64(_compile)
1962    0.002    0.000    0.005    0.000 {built-in method builtins.min}
3830    0.002    0.000    0.003    0.000 enum.py:515(new)
48    0.002    0.000    0.002    0.000 {method ‘set_ciphers’ of ‘_ssl._SSLContext’ objects}
148    0.002    0.000    0.002    0.000 {built-in method posix.getcwd}
10300    0.002    0.000    0.003    0.000 parser.py:320(<genexpr>)
3843    0.002    0.000    0.008    0.000 enum.py:265(call)
6335    0.002    0.000    0.002    0.000 {built-in method builtins.getattr}
3642/3195    0.002    0.000    0.021    0.000 {built-in method builtins.hasattr}
1563    0.002    0.000    0.005    0.000 enum.py:801(and)
225    0.002    0.000    0.002    0.000 sre_compile.py:250(_optimize_charset)
4681    0.002    0.000    0.002    0.000 sre_parse.py:232(__next)
6892    0.002    0.000    0.002    0.000 {method ‘decode’ of ‘bytes’ objects}
173    0.002    0.000    0.002    0.000 {method ‘read’ of ‘_io.FileIO’ objects}

It appears that the culprit was (as I suspected) the amount of network calls that are being made to the wordpress API. It turns out that SSL can be a bit expensive.

By default the wordpress API returns 10 posts per page. Updating this value to 100 decreased the time spent making network calls and overall function calls by almost 50%!

Results after per_page=100

        145834 function calls (142393 primitive calls) in 2.679 seconds

Ordered by: internal time


ncalls  tottime  percall  cumtime  percall filename:lineno(function)
186    2.364    0.013    2.364    0.013 {method ‘read’ of ‘_ssl._SSLSocket’ objects}
5    0.073    0.015    0.073    0.015 {method ‘do_handshake’ of ‘_ssl._SSLSocket’ objects}
5    0.043    0.009    0.043    0.009 {method ‘connect’ of ‘_socket.socket’ objects}
5    0.026    0.005    0.026    0.005 {method ’load_verify_locations’ of ‘_ssl._SSLContext’ objects}

Lessons

Profiling is great. Instead of guessing why my code is slow, I can ask python to tell me explicitly.

Most importantly, for the real world. AWS Lambda bills by the nearest 100 milliseconds.

Duration is calculated from the time your code begins executing until it returns or otherwise terminates, rounded up to the nearest 100ms. The price depends on the amount of memory you allocate to your function.
So in a model like this, reducing the total time for your code to run from 6 seconds to 3 seconds will also reduce your bill by 50%.

Thank you for reading! Share your thoughts with me on bluesky, mastodon, or via email.

Check out some more stuff to read down below.

Most popular posts this month

Recent Favorite Blog Posts

This is a collection of the last 8 posts that I bookmarked.

Articles from blogs I follow around the net

MusicBrainz Picard identifies songs from *.mp3 files and automatically fixes metadata

In my first attempt to switch from streaming to move back to listening to *.mp3 files, one of the issues I encountered was organization: how to standardize the metadata of the songs? The solution I was familiar with at the time — manually editing each son…

via Manual do Usuário April 24, 2025

Google's control of the web could be coming to an end

It's been hard to avoid the US government's antitrust case against Meta lately, since CEO Mark Zuckerberg spent three days in front of the cameras in Congress, testifying about his company's alleged anti-competitive tactics. But another equall…

via The Torment Nexus April 24, 2025

$5 million in tokens stolen from ZKsync

An attacker compromised an admin account belonging to the ZKsync Ethereum layer-2 project, which is built by Matter Labs. By doing so, they were able to steal approximately $5 million worth of the ZK token, which the project said wer…

via Web3 is Going Just Great April 24, 2025

Generated by openring