Tutorial

How to profile your Python code แง๊น ๆ 🏎️

By Arnon Puitrakul - 11 ตุลาคม 2020

How to profile your Python code แง๊น ๆ 🏎️

เวลาเราเขียนโปรแกรม ไม่ว่าจะภาษาอะไรก็ตาม เราก็จะเขียน ๆ ไป เพื่อให้แก้ปัญหาที่เราต้องการได้ แต่พอถึงจุดนึง เราก็จะพบว่า ทำไมโปรแกรมของเรามันใช้เวลาในการทำงานนานมาก ๆ เป็นคำถามที่ดูสั้น และ น่าจะตอบง่าย แต่บอกเลยว่า มันตอบยากมาก โดยเฉพาะ เมื่อเราต้องทำงานกับ Code มหาศาล ถ้าเราต้องมานั่งหาทั้งหมดเอง ไม่น่าใช่เรื่องตลกแน่ ๆ วันนี้เราจะพามารู้จักกับเครื่องมือที่ Python เตรียมมาให้เรา เพื่อให้เราสามารถ Profiling การทำงานของโปรแกรมของเราได้ง่ายขึ้นกัน

วิธีบ้าน  ๆ เอาง่าย

เริ่มแรกที่เรามีความพยายามในการจะ Profiling Code ของตัวเอง ตอนนั้นเราไม่ได้มานั่งหาข้อมูล หรืออ่านเพิ่มเติมเลย ตอนนั้นเราทำง่ายมาก ๆ คือ เรารู้ว่า ใน Python มี Package ที่ชื่อ Time และมี Function ชื่อ time() มันจะให้ค่ากลับมาเป็น UNIX Time ถ้าเราเอาเวลาเริ่ม กับ เวลาจบ มาลบกัน เราก็จะได้เวลาในการทำงาน หน่วยเป็นวินาทีออกมาทันที

import time

start_time = time.time()
# DO STH
elapsed_time = time.time() - start_time
print('Elasped Time', elapsed_time, 'Second(s)')

แต่ปัญหาของมันคือ ถ้า Code ของเรามันมีการสั่งให้อุปกรณ์หยุดการทำงานระหว่างนั้น แต่เราไม่ต้องการที่จะวัดเวลาตรงนั้น เราก็สามารถทำได้อีกเช่นกันโดยการใช้ Function ชื่อว่า process_time

import time

def process_time () :
	start_time = time.process_time()
    # DO STH
    sleep(1)
    elapsed_time = time.process_time() - start_time

ด้วย 2 วิธีการนี้ ก็ทำให้เราสามารถวัดผลคร่าว ๆ ออกมาได้แล้วว่า โปรแกรมของเราใช้เวลาในการทำงานนานแค่ไหนกัน แต่ทั้งหมดมันเป็นการวัดทั้งโปรแกรม ปัญหาคือ ถ้าเราต้องการที่จะแก้ปัญหา เพื่อที่จะลดเวลาในการทำงานของโปรแกรมเรา เราจะต้องรู้ว่า เราจะแก้ตรงไหน นั่นแหละคือ ปัญหาต่อไป

ถ้าเราใช้วิธีการทั้ง 2 ที่เราบอกไป เราก็ต้องไล่คล่อม time.time() ไปเรื่อย ๆ เพื่อให้เราเห็นภาพมากขึ้นเรื่อย ๆ ว่า ตรงไหน มันทำงานใช้เวลาเท่าไหร่ก็ว่ากันไป ซึ่ง ถ้า Code ของเรามีหลายหมื่นบรรทัด และ แต่ละรอบ ใช้เวลาทำงานไม่ต่ำกว่า 5 ชั่วโมง เราบอกเลยว่า ไม่ตลกแน่ ๆ ทำให้มันต้องมีวิธีอื่น ๆ ในจับคนช้าหนึ่งนายแน่นอน

cProfile คือเพื่อนที่ดีของเรา

Python ได้เตรียมอีกเครื่องมือมาให้เราในการทำ Profiling นั่นคือ cProfile โดยที่มันจะวัดเวลาการทำงานของแต่ละส่วนของ Code มาให้เราเลย พร้อมกับ บอกได้อีกว่า Function นี้ถูกเรียกกี่ครั้ง อาจจะยังไม่เห็นภาพ เราจะลองด้วยการเขียน Code สำหรับหาจำนวน Fibonacci ออกมาละกัน โจทย์โคตรคลาสสิก

def fibo (n) :
	result = 0
	for i in range (n)
    	result += n
    return result

สั้น ๆ ง่าย ๆ เราเขียนตรง ๆ เลยคือ เราให้มันค่อย ๆ บวกไปเรื่อย ๆ ตามปกติ ไม่ได้เล่นท่าอะไรเลย ในการเรียกใช้ cProfile ที่ง่ายที่สุด เราสามารถเรียกผ่านคำสั่ง run() ใน cProfile ได้ตามตัวอย่างด้านล่างนี้

>>> import cProfile

>>> cProfile.run('fibo(1000000)')

4 function calls in 0.069 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.069    0.069    0.069    0.069 <stdin>:1(fibo)
        1    0.000    0.000    0.069    0.069 <string>:1(<module>)
        1    0.000    0.000    0.069    0.069 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

หรืออีกวิธี ถ้าเราต้องการที่จะวัดผลของทั้งโปรแกรม เพื่อให้เห็นภาพรวมการทำงานก่อน เราไม่จำเป็นต้องไปคล่อม main() ด้วย cProfile ก็ได้ เราสามารถเรียกให้มันใช้ cProfile ผ่าน Command Line ได้ผ่าน Command ด้านล่างนี้

python -m cProfile <input_source>

เท่านี้ เราก็สามารถที่จะสั่ง Profile Code ของเราได้อย่างง่ายดายแล้ว โดยที่เราไม่ต้องเอา Code ไปคล่อม สุดท้าย จากการรันผ่าน Command Line มันทำให้เราเห็นภาพรวมเลยว่า ตรงไหนมันเกิดอะไรขึ้น เพื่อให้เรา Code ไปคล่อมเพื่อให้เราได้ข้อมูลการทำงานที่ละเอียดขึ้นได้

สำหรับใครที่นิยมการ Profile อย่างละเอียดรายบรรทัด เราแนะนำให้ไปใช้ line_profiler ตัวนั้นเราจะเห็นเป็นรายบรรทัดเลยว่า มันใช้เวลาเท่าไหร่ อย่างละเอียด แต่สำหรับเราเอง เราว่าไม่ได้จำเป็นขนาดนั้น การที่เรารู้ขนาดรายบรรทัด มันไม่ได้บอกอะไรเราเท่าที่ควร เราก็ใช้แค่ cProfile ก็ทำให้เราเห็นข้อมูลมากพอแล้วว่าเราควรจะ Optimise ตรงไหน เพื่อให้มันใช้เวลาน้อยลง

5 function calls in 0.067 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.067    0.067 better_loop.py:1(<module>)
        1    0.067    0.067    0.067    0.067 better_loop.py:1(fibo)
        1    0.000    0.000    0.067    0.067 better_loop.py:7(main)
        1    0.000    0.000    0.067    0.067 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

กลับมาที่ผลลัพธ์จาก cProfile กันต่อ คำถามต่อไปน่าจะถามว่า แล้วเราจะอ่านผลยังไง และมันบอกอะไรเราบ้าง เริ่มจากบรรทัดแรกคือ มันบอกว่า มันมีการเรียก Function ไปทั้งหมด 5 รอบ โดยใช้เวลาไปทั้งหมด 0.067 ก็ถือว่าเป็นข้อมูลเบื้องต้นพอตัวสำหรับการ Profile

ต่อไปจะเป็น ตารางทั้งหมด 6 Columns ด้วยกัน เริ่มจาก ncalls คือจำนวนในการเรียก Function ทั้งหมด ที่ถ้าเราเอาทั้งหมดมาบวกกัน มันจะได้เท่ากับจำนวน Function Call ที่อยู่ในบรรทัดแรก

tottime คือเวลาทั้งหมดที่อยู่ใน Function นั้น ๆ ไม่นับเวลาในการทำงานของ Function อื่นเมื่อเราไปเรียกมันซ้อนเข้าไป และ percall จะสอดคล้องกับ tottime หารด้วย ncalls

cumtime หรือ Cumulative Time Spend คือเวลาในทั้งหมดที่อยู่ใน Function นั้น ๆ นับพวกเวลาในการทำงานของ Sub-Function ทั้งหมดที่เราเรียกซ้อนลงไปด้วย ทำให้ cumtime ส่วนใหญ่จะมีจำนวนเยอะกว่า หรือใกล้เคียงกับ tottime และเกือบสุดท้ายคือ percall รอบที่ 2 คือ การเอา cumtime หารด้วย ncalls เหมือนกัน

ช่องสุดท้ายเป็นชื่อไฟล์ และ Function ที่ถูกเรียก สาเหตุที่มันต้องมีขื่อไฟล์ด้วย เพราะบางที เราอาจจะไปเรียกใช้ Code ที่อยู่ไฟล์อื่นหรือ อาจเป็น Module อื่น ๆ จะได้บอกได้ว่ามันอยู่ที่ไหน เช่น better_loop.py:7(main) ก็คือ อยู่ในไฟล์ชื่อ better_loop.py บรรทัดที่ 7 และ Function ชื่อ main นั่นเอง

def factorial (n) :
    result = 1
    for i in range(1,n+1) :
        result *= i
    return result

def main () :
    factorial(10000)

if __name__ == "__main__":
    main()
factorial_loop.py

ทดลอง Profile โปรแกรมกัน

เรามาลองอะไรสนุก ๆ กันบ้างดีกว่า ที่เราติดค้างไว้ว่า ถ้าจำนวน Function Call เยอะมันมีผลต่อเวลาในการทำงานของโปรแกรม เราลองเขียนโปรแกรมง่าย ๆ ในการหา Factorial ขึ้นมา การทำงานทั้งหมด เราก็เขียนขึ้นมาง่าย ๆ ตรง ๆ คือ เราก็คูณไปเรื่อย ๆ เลย

import sys
sys.setrecursionlimit(10**6) 

def factorial (n) :
    if n == 1 :
        return n
    else :
        return n * factorial(n-1)

def main() :
    factorial(10000)

if __name__ == "__main__":
    main()
factorial_recursive.py

และ Code อีกชุด เป็นโปรแกรมสำหรับหา Factorial เช่นเดียวกัน แต่เราใช้วิธีการเขียนที่แตกต่างออกไป คือการใช้ Recusive ในการเขียนแทน สำหรับคนที่อาจจะไม่คุ้นเคย สั้น ๆ คือ มันเป็นการเรียกตัวเองไปเรื่อย ๆ นั่นแหละ โดยที่เราจะกำหนด 2 ส่วนด้วยกันคือ Base Case และ Recursive Case คือ เงื่อนไขที่เราจะให้มันหยุดเรียกตัวเอง และ เงื่อนไขที่เรียกตัวเองตามลำดับ ตัวอย่างนี้ Base Case คือ เรารู้ว่า 1! = 1 เราก็คืนค่าเป็น 1 กลับไปเลย ไม่ต้องเรียกตัวเองเพื่อคำนวณแล้ว ส่วนที่เหลือจะไปตกที่ Recursive Case ทั้งหมดคือ ให้เอาตัวเองไปคูณกับผลลัพธ์ของ Function ตัวเอง แต่เป็นตัวก่อนหน้า มองภาพให้ง่ายขึ้นอีก เหมือนเราบอกว่า เราอยากหา 4! เราก็จะเอา 4 x 3 x 2 x 1 สิ่งที่เราเขียนลงไปใน Recursion Case คือ 4 x 3! ก็คือเหมือนกันนั่นเอง

ส่วน Code 2 บรรทัดแรก ไม่ต้องไปสนใจมัน มันเป็นการไปกำหนด Limit ของ Recursion ใน Python เฉย ๆ พึ่งมารู้ตอนที่เขียนครั้งแรกนี่แหละ ก็ งง ว่ามันมีการ Limit ด้วยเหรอฮ่า ๆ

5 function calls in 0.021 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.021    0.021 factorial_loop.py:1(<module>)
        1    0.021    0.021    0.021    0.021 factorial_loop.py:1(factorial)
        1    0.000    0.000    0.021    0.021 factorial_loop.py:7(main)
        1    0.000    0.000    0.021    0.021 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

ตัวนี้เป็นผลจากการรัน Factorial ที่เราใช้ Loop ปกติ มันจะใช้เวลาอยู่ที่ 0.021 วินาทีเท่านั้น และ จำนวน Function Call อยู่ที่ 5 เท่านั้น เพราะงานทั้งหมด เรา Loop อยู่ใน Function ที่ชื่อ factorial() ไปเรียบร้อยแล้ว เราจะเห็นได้เลยว่า มันใช้เวลาทั้งหมดไปกับ factorial() ไปหมดเลย ซึ่ง มันก็ Make Sense เพราะมันเป็นส่วนที่การคำนวณเกิดขึ้นทั้งหมด

10005 function calls (6 primitive calls) in 0.030 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.030    0.030 factorial_recursive.py:1(<module>)
        1    0.000    0.000    0.030    0.030 factorial_recursive.py:10(main)
  10000/1    0.030    0.000    0.030    0.030 factorial_recursive.py:4(factorial)
        1    0.000    0.000    0.030    0.030 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {built-in method sys.setrecursionlimit}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
       

มาที่ Version ที่เราใช้ Recursion ในการ Implement กันบ้าง เราจะเห็นว่า เวลาในการทำงานเพิ่มขึ้นมาเป็น 0.030 วินาที เยอะกว่าแบบ Loop เฉย ๆ อยู่นิดหน่อย (นี่ขนาดหายังไม่เยอะ) แต่สิ่งที่เพิ่มขึ้นอย่างน่าตกใจเลยคือ จำนวนของ Function Call ที่เพิ่มขึ้นมาถึง 10,000 Function Call เลยทีเดียว เพราะเราไปเรียกมันเองไงเล่า

ที่ ncalls ของ factorial เราจะเห็นว่า มันเขียนแปลก ๆ คือ 10000/1 ไม่เหมือนเพื่อน ๆ เลย 10,000 แรกคือ จำนวนของ Function Call ที่มันเรียกตัวเอง และ 1 ด้านหลังมาจาก Function Call ที่ Function อื่นเรียกมา ในที่นี้ก็คือ main() นั่นเอง

สิ่งที่เราอยากจะบอกจากการทดลองนี้คือ ถึงโปรแกรมเราจะทำงานได้ผลลัพธ์เหมือนกัน แต่การเขียนโปรแกรมที่แตกต่างกัน ก็ทำให้เกิดความแตกต่างของ Performance ได้มหาศาล ในตัวอย่างนี้ เราแค่เปลี่ยนวิธีการเขียนไปนิดเดียว ก็ทำให้เวลาในการทำงานต่างออกไปพอตัว ดังนั้น หน้าที่ของเราที่นอกจากจะเขียนโปรแกรมให้ได้ผลลัพธ์ที่ถูกต้องแล้ว ก็ต้องทำให้มันทำงานได้เร็วด้วย ซึ่งการจะทำได้ ความรู้พื้นฐานที่เป็น Foundation ของ Computer Science จึงยังคงเป็นเรื่องที่สำคัญอยู่ไงละ

สรุป

วันนี้เราก็พาทุกคนมาทำความรู้จักกับการ Profiling Code ของเราในภาษา Python กัน ตั้งแต่วิธีบ้าน ๆ อย่างการคล่อม Code ด้วยการนับเวลาในการทำงาน จนไปถึงการทำ Profiling ที่ละเอียดขึ้นด้วยการใช้ cProfile ทั้ง 2 เครื่องมือที่เราเอามาเล่าให้อ่านในวันนี้ น่าจะทำให้หลาย ๆ คนสามารถเอาไปปรับใช้กับการทำงานได้เยอะมากแล้ว สำหรับคนที่อยากจะศึกษาเพิ่ม ลองไปดูใน Document ของ Python ในส่วนของ Debugging และ Profilling เพิ่มเติมได้ ในนั้นมันจะมีเครื่องมือหลาย ๆ อย่างที่ช่วยงานเราได้เยอะมาก

สำหรับคนที่ถามาเรื่องของการทำ Memory Profiling เราขอยกยอดไปในบทความต่อ ๆ ไปละกัน เพราะมันมีรายละเอียด และ หลักการ ในการทำงานที่เยอะพอตัว ใส่ไว้ด้วยกันในบทความนี้เกรงว่าจะยาวไป

Read Next...

จัดการข้อมูลบน Pandas ยังไงให้เร็ว 1000x ด้วย Vectorisation

จัดการข้อมูลบน Pandas ยังไงให้เร็ว 1000x ด้วย Vectorisation

เวลาเราทำงานกับข้อมูลอย่าง Pandas DataFrame หนึ่งในงานที่เราเขียนลงไปให้มันทำคือ การ Apply Function เข้าไป ถ้าข้อมูลมีขนาดเล็ก มันไม่มีปัญหาเท่าไหร่ แต่ถ้าข้อมูลของเราใหญ่ มันอีกเรื่องเลย ถ้าเราจะเขียนให้เร็วที่สุด เราจะทำได้โดยวิธีใดบ้าง วันนี้เรามาดูกัน...

ปั่นความเร็ว Python Script เกือบ 700 เท่าด้วย JIT บน Numba

ปั่นความเร็ว Python Script เกือบ 700 เท่าด้วย JIT บน Numba

Python เป็นภาษาที่เราใช้งานกันเยอะมาก ๆ เพราะความยืดหยุ่นของมัน แต่ปัญหาของมันก็เกิดจากข้อดีของมันนี่แหละ ทำให้เมื่อเราต้องการ Performance แต่ถ้าเราจะบอกว่า เราสามารถทำได้ดีทั้งคู่เลยละ จะเป็นยังไง เราขอแนะนำ Numba ที่ใช้งาน JIT บอกเลยว่า เร็วขึ้นแบบ 700 เท่าตอนที่ทดลองกันเลย...

Humanise the Number in Python with "Humanize"

Humanise the Number in Python with "Humanize"

หลายวันก่อน เราทำงานแล้วเราต้องการทำงานกับตัวเลขเพื่อให้มันอ่านได้ง่ายขึ้น จะมานั่งเขียนเองก็เสียเวลา เลยไปนั่งหา Library มาใช้ จนไปเจอ Humanize วันนี้เลยจะเอามาเล่าให้อ่านกันว่า มันทำอะไรได้ แล้วมันล่นเวลาการทำงานของเราได้ยังไง...

ทำไม 0.3 + 0.6 ถึงได้ 0.8999999 กับปัญหา Floating Point Approximation

ทำไม 0.3 + 0.6 ถึงได้ 0.8999999 กับปัญหา Floating Point Approximation

การทำงานกับตัวเลขทศนิยมบนคอมพิวเตอร์มันมีความลับซ่อนอยู่ เราอาจจะเคยเจอเคสที่ เอา 0.3 + 0.6 แล้วมันได้ 0.899 ซ้ำไปเรื่อย ๆ ไม่ได้ 0.9 เพราะคอมพิวเตอร์ไม่ได้มองระบบทศนิยมเหมือนกับคนนั่นเอง บางตัวมันไม่สามารถเก็บได้ เลยจำเป็นจะต้องประมาณเอา เราเลยเรียกว่า Floating Point Approximation...