Python Profile – Ứng Dụng Nhanh Chậm Do Đâu?
Là một lập trình viên Python, bạn sẽ có những hành động gì khi ứng dụng của bạn bị than phiền là chậm ?
Chắc là bạn sẽ phải lên danh sách các event nào mà khách hàng đang sử dụng và thấy nó chậm rồi. Sau đó thì sẽ phải kiểm tra xem thời gian phản hồi thực sự của các event đó đang là bao nhiêu. Quá trình thu thập thông tin này được gọi là “Profiling” và kết quả của quá trình thu được được gọi là “Profile” của ứng dụng.
Profile là gì ? Tại sao phải profiling ?
Profiling/Profile là một khái niệm mà bất kể lập trình viên Python chuyên nghiệp nào cũng phải biết (gần như một kỹ năng mà bắt buộc với những senior developer).
Profiling là một quá trình thực hiện kiểm tra tốc độ thực thi, dung lượng bộ nhớ RAM/ổ cứng, phần trăm CPU chiếm dụng của các đoạn source code cụ thể (function, một hoặc cả cụm câu lệnh).
Tổng hợp các kết quả và đưa ra profile của phần cần theo dõi theo các tiêu chí trên. Từ profile, các lập trình viên có kinh nghiệm sẽ cùng nhau phân tích, mổ xẻ và đưa ra các vấn đề xem ứng dụng đang bị “nghẽn” (bottlenecks) ở đâu, quyết định về việc thực hiện refactor code như thế nào để giải quyết được bài toán performance của ứng dụng.
Thông thường thì quá trình profiling sẽ được thực hiện:
TH1. Ngay trong thời gian thực hiện lập trình (nếu có đủ thời gian hoặc có yêu cầu hoặc tùy vào “tâm” của người làm lập trình).
TH2. Trong quá trình thực hiện system-testing hoặc performance testing, các tester hoặc developer sẽ đặt các đoạn code thực hiện đo đạc thông tin.
TH3. Khi có các cảnh báo không tốt trên hệ thống giám sát về thời gian phản hồi ứng dụng, chiếm dụng bộ nhớ, chiếm dụng CPU.
TH4. Khi nhận được phản hồi tiêu cực từ phía khách hàng/user.
Nếu rơi vào TH1 thì chi phí để sản xuất phần mềm sẽ phải bỏ thêm phần thời gian đặt các đoạn đo đặc thông tin. Với các senior developer hoặc các lập trình viên có kinh nghiệm, chi phí này có thể rất nhỏ vì mỗi dòng code có thể họ đã từng làm ở đâu đó và nó đã được “kiểm chứng” rồi. Đây cũng chính là một trong những sự khác biệt của fresher/junior và senior developer.
Chi phí sản xuất và những điều tệ hại sẽ tăng dần nên khi rơi vào TH2 –> TH3 –> TH4.
Phần lớn việc phát hiện sớm các vấn đề của ứng dụng là thời gian phản hồi (các tài nguyên RAM, CPU, HDD bị thiếu cũng dẫn đến thời gian phản hồi ứng dụng lâu) nên khi Profiling, việc đầu tiên cần quan tâm đó là thời gian thực thi. Bài viết này, tôi sẽ hướng dẫn các bạn các cách để thực hiện profiling theo dõi thời gian phản hồi của các đoạn mã/ứng dụng.
Cách cơ bản thực hiện profiling theo dõi thời gian
Đầu tiên chúng ta sẽ phải xác định đối tượng của profile: Xây dựng cho toàn bộ ứng dụng, cho module, cho function hay cho một block-code cụ thể.
Macro profile: Xây dựng profile cho toàn bộ ứng dụng hoặc những module lớn của ứng dụng. Toàn bộ những thông tin trong quá trình hoạt động sẽ được đưa vào thống kê. Thông thường phần này phải sử dụng công cụ thống kê theo dõi.
Micro profile: Xây dựng profile cho những phần nhỏ hoặc từng phần của ứng dụng. Cũng có thể hiểu là sẽ thực hiện theo dõi hoạt động của từng block-code, function. Phần này chủ yếu là sử dụng việc cài đặt trực tiếp trên mã nguồn.
Trong bài viết này, tôi muốn hướng đến phần micro-profile, những thứ mà lập trình viên chúng ta có thể tự làm được.
Tôi sẽ thực hiện “đo đạc” thời gian thực hiện của các function trong ví dụ mà tôi đã từng viết tại bài viết Tìm Số Nguyên Tố Trong Lập Trình Bằng Cách Nào?
import random
import math
def is_prime_basic(number):
if number < 2:
return False
for value in range(2, number):
if number % value == 0:
return False
return True
def is_prime_sqrt(number):
if number < 2:
return False
max_range = int(math.sqrt(number)) + 1
for value in range(2, max_range):
if number % value == 0:
return False
return True
def is_prime_optimal(number):
if number in [2, 3, 5]:
return True
if number % 2 == 0 or number % 3 == 0 or number % 5 == 0 or number < 2:
return False
if number < 49:
return True
if (number % 7) == 0 or (number % 11) == 0 or (number % 13) == 0 or (number % 17) == 0 or \
(number % 19) == 0 or (number % 23) == 0 or (number % 29) == 0 or (number % 31) == 0 or \
(number % 37) == 0 or (number % 41) == 0 or (number % 43) == 0 or (number % 47) == 0:
return False
if number < 2809:
return True
max_range = int(math.sqrt(number)) + 1
for value in range(53, max_range, 2):
if number % value == 0:
return False
return True
Simple Profiling
Cách đơn giản nhất để thực hiện theo dõi thời gian thực hiện là đặt 2 biến dữ liệu thời gian ở đầu và cuối block-code muốn theo dõi.
Có nhiều cách để sinh ra các biến thời gian, tôi thường dùng module timeit để có thể sinh ra được khoảng cách thời gian đến mức 10^-n (với nhiều nhiều số 0 ở hàng thập phân).
Đầu tiên, tôi sẽ tạo file basic_profile.py chứa code 3 function is_prime_basic, is_prime_sqrt, is_prime_optimal ở trên và bổ sung thêm các đoạn code thực hiện profiling bên dưới:
def run_basic_function(number):
start = timeit.default_timer()
result = is_prime_basic(number)
stop = timeit.default_timer()
print("Basic-function {0}: {1}: {2}(second)".format(number, result, (stop - start)))
return stop - start
def run_sqrt_function(number):
start = timeit.default_timer()
result = is_prime_sqrt(number)
stop = timeit.default_timer()
print("Sqrt-function {0}: {1}: {2}(second)".format(number, result, (stop - start)))
return stop - start
def run_optimal_function(number):
start = timeit.default_timer()
result = is_prime_optimal(number)
stop = timeit.default_timer()
print("Optimal-function {0}: {1}: {2}(second)".format(number, result, (stop - start)))
return stop - startChọn một số number ngẫu nhiên, và thực hiện các function run_basic_function, run_sqrt_function, run_optimal_function để lấy được profile về thời gian thực thi của 3 function trên.
if __name__ == "__main__":
number = random.randint(1, 10**8)
run_basic_function(number)
run_sqrt_function(number)
run_optimal_function(number)
Thực hiện chạy file basic_profile.py và thu được kết quả:
> python basic_profile.py
Basic-function 72096783: False: 6.899999999997186e-06(second)
Sqrt-function 72096783: False: 5.299999999999749e-06(second)
Optimal-function 72096783: False: 1.8999999999991246e-06(second)
> python basic_profile.py
Basic-function 10848917: True: 0.7584309(second)
Sqrt-function 10848917: True: 0.0002996999999999028(second)
Optimal-function 10848917: True: 0.00013299999999993872(second)Một cách ngắn gọn hơn, thay vì phải viết 3 function để thực hiện chung một công việc, chúng ta có thể viết một fucntion dạng tổng quát và để gọi vào với các tham số tương ứng. Tạo file basic_benchmark_profile.py với 3 function is_prime_basic, is_prime_sqrt, is_prime_optimal sau đó bổ sung thêm đoạn code bên dưới:
def benchmark_function(function, params):
start = timeit.default_timer()
result = function(params)
end = timeit.default_timer()
print("{0} - params: {1} #Result: {2} #Total time: {3}(second)".format(function.__name__, params, result, (end - start)))
if __name__ == "__main__":
number = random.randint(1, 10**8)
benchmark_function(is_prime_basic, number)
benchmark_function(is_prime_sqrt, number)
benchmark_function(is_prime_optimal, number)Thực hiện chương trình:
> python .\basic_benchmark_profile.py
is_prime_basic - params: 36127468 #Result: False #Total time: 8.29999999999928e-06(second)
is_prime_sqrt - params: 36127468 #Result: False #Total time: 6.4000000000001556e-06(second)
is_prime_optimal - params: 36127468 #Result: False #Total time: 1.7000000000003124e-06(second)
> python .\basic_benchmark_profile.py
is_prime_basic - params: 46251852 #Result: False #Total time: 7.200000000002343e-06(second)
is_prime_sqrt - params: 46251852 #Result: False #Total time: 6.099999999998468e-06(second)
is_prime_optimal - params: 46251852 #Result: False #Total time: 2.8000000000007186e-06(second)
Use decorator function for profiling.
Cách này, chúng ta cũng sử dụng phương pháp đặt theo dõi thời gian thủ công nhưng thay vì yêu cầu “thủ công” việc đưa ra thời gian thực hiện vào từng block-code bên trong function thì chúng ta sẽ thực hiện mặc định cứ gọi đến function là sẽ hiển thị ra thời gian thực hiện.
Để thực hiện được, chúng ta sẽ sử dụng một chức năng khá thú vị trong Python là decorator.
Khái niệm về decorator, tôi sẽ trình bày trong một bài viết khác. Trong khuôn khổ bài viết này, bạn chỉ cần hiểu đầu vào của decorator function benchmark_me là function và đầu vào của function mà chúng ta muốn thực hiện profiling.
Tạo file decorator_benchmark_profile.py với function bên dưới và bổ sung thêm đoạn gán decorator function và 3 function is_prime_basic, is_prime_sqrt, is_prime_optimal
def benchmark_me():
def decorator(function):
def wraps(*args, **kwargs):
start = timeit.default_timer()
result = function(*args, **kwargs)
end = timeit.default_timer()
print("{0} - params: {1} {2} #result: {3} total time: {4}(second)".format(function.__name__, str(*args), str(*kwargs) , result, (end - start)))
return result
return wraps
return decorator
@benchmark_me()
def is_prime_sqrt(number):
if number < 2:
return False
max_range = int(math.sqrt(number)) + 1
for value in range(2, max_range):
if number % value == 0:
return False
return True
Sau khi áp dụng technique này vào thì chúng ta chỉ cần gọi đến is_prime_sqrt(number) là đã thu được thời gian thực hiện thực hiện của function.
if __name__ == "__main__":
number = random.randint(1, 10**8)
is_prime_basic(number)
is_prime_sqrt(number)
is_prime_sqrt(number)Gọi vào chương trình:
> python .\decorator_benchmark_profile.py
is_prime_basic - params: 58320833 #Result: True #Total time: 4.7889745999999995(second)
is_prime_sqrt - params: 58320833 #Result: True #Total time: 0.0009272999999998532(second)
is_prime_sqrt - params: 58320833 #Result: True #Total time: 0.0010278000000001342(second)Sử dung cProfile để profiling
cProfile là một thư viện được cung cấp “chính chủ” bởi Python để hỗ trợ các lập trình thực hiện Profiling các source code của mình.
Kết quả profile trả về khá là chi tiết, đủ các thông tin để các lập trình viên quyết định các action tiếp theo.
Bây giờ tôi sẽ lưu đoạn source code kiểm tra số nguyên tố phía trên và thêm đoạn code phía dưới này của tôi thành file: find_prime.py
def run_function(function, numbers):
for number in numbers:
function(number)
if __name__ == "__main__":
numbers = [80909548, 64284912, 32561271, 59635875, 43704113, 42511163, 7564624, 62719360, 29119365, 49141585]
method = sys.argv[-1]
if method == 'basic':
run_function(is_prime_basic, numbers)
elif method == 'sqrt':
run_function(is_prime_sqrt, numbers)
else:
run_function(is_prime_optimal, numbers)method = sys.argv[-1] là để lấy ra giá trị mà tôi sẽ truyền vào trên câu lệnh gọi đến cProfile.
Tại màn hình command-line (cmd/terminal/…), chúng ta gọi đến file find_prime.py để thực hiện lấy profile của các function: python -m cProfile -s calls find_prime.py –> thực hiện lấy profile của function: is_prime_optimalpython -m cProfile -s calls find_prime.py basic –> thực hiện lấy profile của function: is_prime_basicpython -m cProfile -s calls find_prime.py sqrt –> thực hiện lấy profile của function: is_prime_sqrt
Trong 3 function trên ví dụ của tôi thì với gọi vào hàm is_prime_basic là mất khoảng 6s nên thời gian hiển thị dễ nhìn hơn so với is_prime_optimal, is_prime_sqrt. (Chi tiết log, các bạn có thể xem tại link github ở phía dưới)
> python -m cProfile -s calls find_prime.py basic
68 function calls in 6.119 seconds
Ordered by: call count
ncalls tottime percall cumtime percall filename:lineno(function)
10 6.119 0.612 6.119 0.612 find_prime.py:4(is_prime_basic)
4 0.000 0.000 0.000 0.000 {built-in method builtins.getattr}
4 0.000 0.000 0.000 0.000 {built-in method builtins.hasattr}
3 0.000 0.000 0.000 0.000 {built-in method _imp.acquire_lock}
3 0.000 0.000 0.000 0.000 {built-in method _imp.release_lock}
2 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:211(_call_with_frames_removed)
2 0.000 0.000 0.000 0.000 {built-in method _thread.allocate_lock}
2 0.000 0.000 0.000 0.000 {built-in method _thread.get_ident}
2 0.000 0.000 0.000 0.000 {method 'get' of 'dict' objects}
2 0.000 0.000 0.000 0.000 {method 'rpartition' of 'str' objects}
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:58(__init__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:78(acquire)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:103(release)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:143(__init__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:147(__enter__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:151(__exit__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:176(cb)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:157(_get_module_lock)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:222(_verbose_message)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:232(_requires_builtin_wrapper)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:342(__init__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:389(parent)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:397(has_location)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:406(spec_from_loader)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:477(_init_module_attrs)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:549(module_from_spec)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:650(_load_unlocked)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:725(find_spec)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:746(create_module)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:754(exec_module)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:771(is_package)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:863(__enter__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:867(__exit__)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:890(_find_spec)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:956(_find_and_load_unlocked)
1 0.000 0.000 0.000 0.000 <frozen importlib._bootstrap>:986(_find_and_load)
1 0.000 0.000 6.119 6.119 find_prime.py:45(run_function)
1 0.000 0.000 6.119 6.119 find_prime.py:1(<module>)
1 0.000 0.000 0.000 0.000 {method 'pop' of 'dict' objects}
1 0.000 0.000 6.119 6.119 {built-in method builtins.exec}
1 0.000 0.000 0.000 0.000 {built-in method _imp.create_builtin}
1 0.000 0.000 0.000 0.000 {built-in method _imp.is_builtin}
1 0.000 0.000 0.000 0.000 {built-in method _imp.exec_builtin}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}Các tham số kết quả: ncalls: tổng số lần gọi đến functions.
ncalls tottime percall cumtime percall filename:lineno(function)10 6.119 0.612 6.119 0.612 find_prime.py:4(is_prime_basic)
Do numbers có 10 phần tử nên sẽ gọi vào function is_prime_basic 10 lần.
tottime: Tổng thời gian sử dụng để thực hiện một function.percall: Bằng tottime / ncallscumtime: Tổng thời gian sử dụng để thực hiện xong phần code, từ khi được gọi cho đến khi kết thúcfilename:lineno(function): Module code và dòng code trong module được gọi đến.
Ngoài cách sử dụng terminal để gọi đến cProfile thì chúng ta cũng có thể import module cProfile vào code để lấy ra kết quả trực tiếp mỗi lần chạy chương trình.
Tạo file cprofile_inside.py, thêm đoạn code vào file:
import cProfile
import functools
import pstats
import tempfile
def profile_me(func):
@functools.wraps(func)
def wraps(*args, **kwargs):
file = tempfile.mktemp()
profiler = cProfile.Profile()
profiler.runcall(func, *args, **kwargs)
profiler.dump_stats(file)
metrics = pstats.Stats(file)
metrics.strip_dirs().sort_stats('time').print_stats(100)
return wraps
@cprofile_me
def run_function(function, numbers):
for number in numbers:
function(number)
Bổ sung thêm function is_prime_basic, is_prime_sqrt, thêm đoạn khởi chạy cho chương trình:
if __name__ == "__main__":
numbers = [80909548, 64284912, 32561271, 59635875, 43704113, 42511163, 7564624, 62719360, 29119365, 49141585]
run_function(is_prime_basic, numbers)
run_function(is_prime_sqrt, numbers)Khi thực hiện gọi từ màn hình terminal, chúng ta sẽ thu được kết quả:
> python .\cprofile_inside.py
Sun Oct 25 10:12:16 2020 C:\Users\TIEUBA~1\AppData\Local\Temp\tmpk76o2ffn
12 function calls in 6.341 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
10 6.341 0.634 6.341 0.634 cprofile_inside.py:24(is_prime_basic)
1 0.000 0.000 6.341 6.341 cprofile_inside.py:19(run_function)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
Sun Oct 25 10:12:16 2020 C:\Users\TIEUBA~1\AppData\Local\Temp\tmpchye6dy7
22 function calls in 0.001 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
10 0.001 0.000 0.001 0.000 cprofile_inside.py:32(is_prime_sqrt)
1 0.000 0.000 0.001 0.001 cprofile_inside.py:19(run_function)
10 0.000 0.000 0.000 0.000 {built-in method math.sqrt}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
Các bạn có thể tìm hiểu kỹ hơn về cProfile theo như tài liệu của Python: https://docs.python.org/3/library/profile.html
Kết
Như đã phân tích từ đầu, việc xây dựng profile cho ứng dụng được viết bằng Python là vô cùng quan trọng, chúng ta nên tập cho mình thói quen theo dõi phản hồi của ứng dụng ngay lúc bắt đầu lập trình giống như viết unit-test cho mỗi module vậy.
Toàn bộ source code của bài viết này được đặt tại github: https://github.com/quangvinh1986/python_profile. Các bạn có thể tham khảo tại đó.
Cảm ơn các bạn đã đọc bài viết.
Post Comment