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()

ทดลอง 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()

และ 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 เราขอยกยอดไปในบทความต่อ ๆ ไปละกัน เพราะมันมีรายละเอียด และ หลักการ ในการทำงานที่เยอะพอตัว ใส่ไว้ด้วยกันในบทความนี้เกรงว่าจะยาวไป