🖼️ See the drawing + lab 🏠 Course home 🌿 Branch on GitHub ✏️ View source

🖼️ आकृती आणि labThe drawing + lab पूर्ण पानावर उघडा ↗Open full page ↗

📋 धडा 03 — Profiling: प्रशिक्षिकेचा clipboard

📍 तुम्ही इथे आहात: 12 पैकी धडा 03 · मागे: lesson-02-benchmarking · पुढे: lesson-04-complexity

📦 या ब्रँचमध्ये काय आहे

धडे 01–02, अधिक profiling: काहीही बदलण्याआधी, वेळ कुठे जातो ते शोधा. Profiler कोणती functions चालतात, किती वेळा, आणि किती काळ ते नोंदवतो. हा धडा Python च्या built-in cProfile मधून call counts वाचतो — counts प्रत्येक machine वर सारखे असतात, वेळा नाहीत — आणि त्यांचा वापर करून एक hot spot शोधून तो दुरुस्त करतो. perf/demo.py मधले profile() आणि perf/sim.py मधले results_slow, results_fast आणि profile_calls.

🧒 5 वर्षांच्या मुलाला समजावल्यासारखे

क्रीडा दिनाचे results छापायला खूप वेळ लागतो. प्रत्येकाचा काहीतरी अंदाज आहे. "Printer जुना आहे!" "बेरजा कठीण आहेत!"

प्रशिक्षिका दीपिका अंदाज करत नाही. ती एक clipboard 📋 घेते आणि results च्या टेबलाशेजारी उभी राहते. कोणीही एखादे काम करताच, ती त्या कामासमोर एक खूण करते.

शेवटी clipboard सांगतो:

"मोठ्या यादीत एखादा धावपटू शोधणे": 2000 खुणा
"एका house ची सर्वोत्तम वेळ शोधणे": 4 खुणा

आणि प्रत्येक "धावपटू शोधणे" म्हणजे 300 नावांची यादी एकेक करत चाळणे. म्हणजे जवळजवळ 300,000 नावांच्या तपासण्या. Printer ठीक होता. शोधणे (lookup) हीच समस्या होती.

म्हणून दीपिका एकदाच bib क्रमांकानुसार लावलेली card box 🗂️ बनवते. आता प्रत्येक lookup म्हणजे एक झटपट उचलणे. Results तेच, आणि हळू काम नाहीसे झाले.

🗺️ आकृती

flowchart LR
    prog["🏃 results program<br/>300 runners · 2000 laps"] --> prof["📋 cProfile<br/>counts every call"]
    prof --> hot["find_runner 2000×<br/>297,098 comparisons"]
    prof --> cold["best_of 4× · results_slow 1×"]
    hot --> fix["🗂️ build a dict by bib once"]
    fix --> after["find_runner 0 comparisons<br/>same results: True"]

🗺️ काढलेली आकृती + एक lab: https://school-edh.pages.dev/performance/lesson-diagrams.html#l03

❓ काय

Profiler — program आपला वेळ (किंवा memory) कुठे खर्च करतो हे सांगणारे tool.
Deterministic (tracing) profiler — प्रत्येक function call आणि return नोंदवतो. cProfile असाच आहे. तो अचूक call counts देतो, पण प्रत्येक call ला थोडा खर्च जोडतो, म्हणून अनेक छोट्या calls असलेला code प्रत्यक्षापेक्षा हळू दिसतो.
Sampling profiler — program चा stack दर second अनेक वेळा पाहतो आणि तो कुठे होता ते मोजतो. कमी overhead, चालू process ला जोडता येतो, production साठी चांगला: py-spy, Linux perf, Scalene. त्याचे आकडे अंदाज आहेत, अचूक counts नाहीत.
ncalls — function किती वेळा call झाले (3/1 म्हणजे एकूण 3 calls, त्यापैकी 1 primitive — recursive call नाही). tottime — function च्या स्वतःच्या आतला वेळ. cumtime — त्याच्या आतला आणि त्याने call केलेल्या सगळ्याचा वेळ. हळू शाखा शोधायला cumtime ने sort करा, काम करणारे function शोधायला tottime ने.
Hot spot — code चा असा छोटा भाग जिथे बहुतेक वेळ जातो. बऱ्याचदा एक किंवा दोन functions च बहुतेक खर्च असतात, म्हणून profile सांगतो की कोणता एक बदल महत्त्वाचा आहे.
Flame graph — अनेक stack samples चे चित्र: प्रत्येक box एक function आहे, त्याची रुंदी म्हणजे तो stack वर किती वेळ होता. वरच्या बाजूचे रुंद boxes हे hot spots आहेत.

🤔 का

कारण लोकांचे अंदाज चुकतात. हळू भाग क्वचितच तिथे असतो जिथे तो हळू "दिसतो", आणि 2% वेळ घेणारा code जलद केल्याने जास्तीत जास्त 2% फायदा होऊ शकतो. आधी profiling केल्याने "हे जलद करा" चे रूपांतर "हे function जलद करा" मध्ये होते, आणि मग धडा 02 चा benchmark ते काम झाले का ते सांगतो.

🔧 कसे (या repo मध्ये)

perf/sim.py मधले sports_day() 300 धावपटू (shuffled क्रमाने) आणि 2000 laps बनवते. results_slow प्रत्येक lap चा धावपटू find_runner ने शोधते, जे यादी चाळते आणि प्रत्येक comparison COUNT["compares"] मध्ये मोजते. results_fast एकदाच bib नुसार dict बनवते. profile_calls(fn, ...) function खऱ्या cProfile खाली चालवते आणि या module ची functions त्यांच्या ncalls सह परत देते (ते comprehension helpers वगळते, जे नव्या Python versions स्वतंत्र functions म्हणून दाखवत नाहीत).

🧪 करून पाहा

python3 perf/demo.py profile
python3 - <<'EOF'
import sys; sys.path.insert(0, "perf"); import sim
runners, laps = sim.sports_day()
for n_laps in (500, 1000, 2000):
    sim.COUNT["compares"] = 0
    _, rows = sim.profile_calls(sim.results_slow, runners, laps[:n_laps])
    print(f"{n_laps:>4} laps → find_runner {dict(rows)['find_runner']:>4}× · {sim.COUNT['compares']:>7,} comparisons")
EOF
python3 -c "import cProfile, sys; sys.path.insert(0, 'perf'); import sim; r, l = sim.sports_day(); cProfile.run('sim.results_slow(r, l)', sort='ncalls')" | head -14

शेवटचा command cProfile चे संपूर्ण table छापतो. त्याचा ncalls column find_runner साठी 2000 सांगतो; त्याचे वेळेचे columns (tottime, cumtime, आणि पहिल्या ओळीतली एकूण वेळ) खऱ्या घड्याळाच्या वेळा आहेत — तुमचे आकडे वेगळे असतील.

✅ तपासा — तुम्हाला काय दिसायला हवे

profile हे छापते:

── Dipika profiles the results program with cProfile: 300 runners, 2000 laps (we read CALL COUNTS, not times)
   find_runner 2000× · best_of 4× · results_slow 1×
   find_runner walks the runner list every time: 297,098 comparisons for 2000 lookups — the hot spot
── fix: build a dict by bib once →   best_of 4× · results_fast 1×
   find_runner comparisons now 0 · same results: True · best 100 m per house (ms) {'blue': 11000, 'green': 11006, 'red': 11006, 'yellow': 11005}

तुमचा snippet हे छापतो:

 500 laps → find_runner  500× ·  74,124 comparisons
1000 laps → find_runner 1000× · 149,300 comparisons
2000 laps → find_runner 2000× · 297,098 comparisons

🏁 तुम्ही आत्ताच काय सिद्ध केले

एकही अंदाज न करता profile ने दोषी शोधला: find_runner, 2000 calls, सुमारे प्रत्येकी 149 comparisons (सरासरी 300 चे निम्मे). दुप्पट laps, दुप्पट काम — म्हणजे 20,000 laps असलेल्या results दिवशी सुमारे 3 million comparisons होतील. उपायाने एक data structure बदलले आणि 0 यादी-चाळण्यांसह तेच results दिले. हेच या संपूर्ण कोर्सचे चक्र आहे: मोजा → profile करा → एक गोष्ट बदला → पुन्हा मोजा.

⚠️ नेहमीच्या चुका

profiling करण्याआधीच optimise करणे ("मला खात्री आहे, छपाईच आहे")
main() चा cumtime वाचून "main हळू आहे" असा निष्कर्ष काढणे — खाली, tottime कडे पाहा
लाखो छोट्या calls असलेल्या code साठी cProfile च्या वेळांवर विश्वास ठेवणे — त्याचा overhead त्या फुगवतो
छोट्या test input वर profiling करणे, जिथे खऱ्या input चा hot spot कधीच दिसत नाही
फक्त laptop वर profiling करणे; production मध्ये वेगळा hot spot असू शकतो (data, cache, load)

🏭 प्रत्यक्ष वापरात

खऱ्या machine वर — एका script चे profile करा आणि प्रत्येक function मध्ये गेलेल्या वेळेनुसार sort करून result उघडा:

python3 -m cProfile -o results.prof make_results.py
python3 -c "import pstats; pstats.Stats('results.prof').sort_stats('cumtime').print_stats(15)"

py-spy आधीच चालू असलेल्या process चे samples घेतो, code न बदलता आणि कमी overhead सह (त्याला sudo लागू शकतो):

py-spy top --pid 12345                          # a live 'top' of Python functions
py-spy record -o flame.svg --pid 12345 --duration 30   # a flame graph
py-spy dump --pid 12345                         # every thread's stack, right now

Linux perf native code सुद्धा पाहतो; Python 3.12 पासून, CPython -X perf वापरून perf मध्ये Python function ची नावे दाखवू शकतो:

perf record -g -- python3 -X perf make_results.py
perf report

🏭 Production मध्ये हे का महत्त्वाचे आहे: खऱ्या service चे profile करण्याचा मार्ग ठेवा — pod वर py-spy, continuous profiler, किंवा auth मागे profiling endpoint. खऱ्या traffic आणि खऱ्या data खालचा hot spot हाच दुरुस्त करण्यासारखा असतो.

⏭️ पुढे

find_runner ने असे काम केले जे यादीच्या आकारासोबत वाढत होते — प्रत्येक lap साठी. हा complexity चा प्रश्न आहे. पुढे: O(n²) विरुद्ध O(n log n), मोजून.

git checkout lesson-04-complexity

📋 Lesson 03 — Profiling: the coach's clipboard

📍 You are here: Lesson 03 of 12 · Previous: lesson-02-benchmarking · Next: lesson-04-complexity

📦 What's in this branch

Lessons 01–02, plus profiling: before you change anything, find where the time goes. A profiler records which functions run, how often, and for how long. This lesson reads call counts from Python's built-in cProfile — counts are the same on every machine, times are not — and uses them to find one hot spot and fix it. profile() in perf/demo.py and results_slow, results_fast and profile_calls in perf/sim.py.

🧒 Explain like I'm 5

The sports-day results take ages to print. Everyone has a guess. "The printer is old!" "The sums are hard!"

Dipika the coach does not guess. She takes a clipboard 📋 and stands next to the results desk. Every time someone does a job, she makes a tick next to that job.

At the end, the clipboard says:

"look up a runner in the big list": 2000 ticks
"find the best time for a house": 4 ticks

And each "look up a runner" means walking down a list of 300 names, one by one. That is nearly 300,000 name checks. The printer was fine. The lookup was the problem.

So Dipika makes a card box sorted by bib number 🗂️ once. Now each lookup is one quick grab. Same results, and the slow job is gone.

🗺️ Diagram

flowchart LR
    prog["🏃 results program<br/>300 runners · 2000 laps"] --> prof["📋 cProfile<br/>counts every call"]
    prof --> hot["find_runner 2000×<br/>297,098 comparisons"]
    prof --> cold["best_of 4× · results_slow 1×"]
    hot --> fix["🗂️ build a dict by bib once"]
    fix --> after["find_runner 0 comparisons<br/>same results: True"]

🗺️ Drawn version + a lab: https://school-edh.pages.dev/performance/lesson-diagrams.html#l03

❓ What

Profiler — a tool that tells you where a program spends its time (or memory).
Deterministic (tracing) profiler — records every function call and return. cProfile is one. It gives exact call counts, but it adds a cost to every call, so code with many tiny calls looks slower than it really is.
Sampling profiler — looks at the program's stack many times a second and counts where it was. Low overhead, can attach to a running process, good for production: py-spy, Linux perf, Scalene. Its numbers are estimates, not exact counts.
ncalls — how many times a function was called (3/1 would mean 3 calls in total, 1 of them primitive — not a recursive call). tottime — time inside the function itself. cumtime — time inside it and everything it called. Sort by cumtime to find the slow branch, by tottime to find the function doing the work.
Hot spot — the small part of the code where most of the time goes. Very often one or two functions are most of the cost, so a profile tells you which one change matters.
Flame graph — a picture of many stack samples: each box is a function, its width is how much of the time it was on the stack. Wide boxes near the top are hot spots.

🤔 Why

Because people guess wrong. The slow part is rarely where it "looks" slow, and speeding up code that takes 2% of the time can win at most 2%. Profiling first turns "make it faster" into "make this function faster", and then lesson 02's benchmark tells you if it worked.

🔧 How (in this repo)

sports_day() in perf/sim.py makes 300 runners (in shuffled order) and 2000 laps. results_slow finds each lap's runner with find_runner, which walks the list and counts every comparison in COUNT["compares"]. results_fast builds a dict by bib once. profile_calls(fn, ...) runs the function under real cProfile and returns this module's functions with their ncalls (it skips comprehension helpers, which newer Python versions no longer show as separate functions).

🧪 Try it

python3 perf/demo.py profile
python3 - <<'EOF'
import sys; sys.path.insert(0, "perf"); import sim
runners, laps = sim.sports_day()
for n_laps in (500, 1000, 2000):
    sim.COUNT["compares"] = 0
    _, rows = sim.profile_calls(sim.results_slow, runners, laps[:n_laps])
    print(f"{n_laps:>4} laps → find_runner {dict(rows)['find_runner']:>4}× · {sim.COUNT['compares']:>7,} comparisons")
EOF
python3 -c "import cProfile, sys; sys.path.insert(0, 'perf'); import sim; r, l = sim.sports_day(); cProfile.run('sim.results_slow(r, l)', sort='ncalls')" | head -14

The last command prints cProfile's full table. Its ncalls column says 2000 for find_runner; its time columns (tottime, cumtime, and the total in the first line) are real clock times — your numbers will differ.

✅ Verify — what you should see

profile prints:

── Dipika profiles the results program with cProfile: 300 runners, 2000 laps (we read CALL COUNTS, not times)
   find_runner 2000× · best_of 4× · results_slow 1×
   find_runner walks the runner list every time: 297,098 comparisons for 2000 lookups — the hot spot
── fix: build a dict by bib once →   best_of 4× · results_fast 1×
   find_runner comparisons now 0 · same results: True · best 100 m per house (ms) {'blue': 11000, 'green': 11006, 'red': 11006, 'yellow': 11005}

Your snippet prints:

 500 laps → find_runner  500× ·  74,124 comparisons
1000 laps → find_runner 1000× · 149,300 comparisons
2000 laps → find_runner 2000× · 297,098 comparisons

🏁 What you just proved

The profile named the culprit without a single guess: find_runner, 2000 calls, about 149 comparisons each (half of 300 on average). Twice the laps, twice the work — so a results day with 20,000 laps would do about 3 million comparisons. The fix changed one data structure and gave the same results with 0 list walks. That is the loop of this whole course: measure → profile → change one thing → measure again.

⚠️ Common mistakes

optimising before profiling ("I'm sure it's the printing")
reading cumtime of main() and concluding "main is slow" — look lower, at tottime
trusting cProfile times for code with millions of tiny calls — its overhead inflates them
profiling a tiny test input, where the hot spot of the real input never shows up
profiling on a laptop only; production may have a different hot spot (data, cache, load)

🏭 In production

On a real machine — profile a script and open the result sorted by the time spent in each function:

python3 -m cProfile -o results.prof make_results.py
python3 -c "import pstats; pstats.Stats('results.prof').sort_stats('cumtime').print_stats(15)"

py-spy samples a process that is already running, with no code change and low overhead (it may need sudo):

py-spy top --pid 12345                          # a live 'top' of Python functions
py-spy record -o flame.svg --pid 12345 --duration 30   # a flame graph
py-spy dump --pid 12345                         # every thread's stack, right now

Linux perf sees native code too; since Python 3.12, CPython can show Python function names in perf with -X perf:

perf record -g -- python3 -X perf make_results.py
perf report

🏭 Why this matters in production: keep a way to profile the real service — py-spy on a pod, a continuous profiler, or a profiling endpoint behind auth. The hot spot under real traffic and real data is the one worth fixing.

⏭️ Next

find_runner did work that grew with the size of the list — for every lap. That is a question of complexity. Next: O(n²) vs O(n log n), counted.

git checkout lesson-04-complexity

← Previousbenchmarking Next →complexity

This page is the lesson's README from the lesson-03-profiling branch, shown here so the whole School stays on one site. Code files open on GitHub at the same branch.