Ruby Performance – Profile trong tối ưu hiệu năng Ruby – Phần 4

Tram Ho

Trong các phần trước, chúng ta đã tìm hiểu các kỹ thuật trong việc tối ưu hoá performance ruby. Nhưng nếu như các kỹ thuật đấy không có hiệu quả thì sao? Câu trả lời đó là profile

Kỹ thuật profile là cách duy nhất trả lời cho câu hỏi là cái gì làm cho code bị chậm?. Trong bài viết này, chúng ta sẽ cùng tìm hiểu những bí mật trong profile mà có thể dễ dàng tìm ra được những thứ gây chậm trong chương trình.

Bài viết này sẽ có 2 phần chính, đó là đo đạc bộ nhớ và CPU được dùng. Phần 2 là chuyển đổi kết quả thu được trước đó để chỉ ra các phần code chạy chậm.

Công cụ được sử dụng trong quá trình profile là ruby-prof. Nó sẽ đo thời gian thực thi của chương trình và sẽ chia nhỏ thành các hàm riêng biệt mà chương trình sử dụng.

Sau khi bạn thực hiện đo đạc từ ruby-prof, bạn có thể trực quan hoá chúng với các công cụ in được xây dựng bởi ruby-prof hay với KCachegrind.

Ngoài ra, chúng ta cần xác đinh rõ quy tắc trong profile CPU. Đầu tiên và quy tắc duy nhất để cho quá trình profile CPU thành công là tắt garbage collector

Đo đạc với Ruby-prof

ruby-prof là gem của Ruby bao gồm cả API và công cụ command-line. Trong Rails, chúng ta có thể kiểm tra một request bằng cách thêm ruby-prof vào trong quá trình middleware.

1. ruby-prof API

VD:

Ta có thể sử dụng block cho ruby-prof:

Có một vài kiểu report cho ruby-prof để in ra kết quả, trên đây ta sử dụng FlatPrinter, nó sẽ hiển thị tổng số thời gian thực thi của mỗi hàm. Bạn sẽ dễ dàng nhìn được các hàm gây tốn thời gian cho CPU.

Khi chạy, ta sẽ có một kết quả profile như sau:

#ruby_prof_example_api1_profile.txt

Thread ID: 70237499659060

Fiber ID: 70237507374720

Total: 0.001111

Sort by: self_time

%selftotalselfwaitchildcallsname
59.980.0010.0010.0000.0002Regexp#match
28.960.0010.0000.0000.0011Class::Date#parse
4.720.0010.0000.0000.0011Global#[Nomethod]
3.810.0000.0000.0000.0001String#gsub!
1.220.0000.0000.0000.0001MatchData#begin
0.670.0000.0000.0000.0001String#[]=
0.380.0000.0000.0000.0001Fixnum#div
0.250.0000.0000.0000.0001MatchData#end

Code trên dành hơn 60% thời gian vào việc tìm ngày được truyền vào qua regular expression. Hầu hết số thời gian còn lại được dùng cho Date#parse, có thể chính là việc khởi tạo object Date.

Bây giờ, hãy cùng tìm hiểu cách sử dụng công dòng lệnh.

2. Công cụ dòng lệnh ruby-prof

Ta có chương trình:

Ta chạy lệnh ruby-prof để thực hiện profile chương trình trên:

Option -p để xác định format output cho profile. Và -m để giới hạn hiển thị cho tất cả các hàm mà mất ít hơn một thời gian cụ thể nào đó. Trong trường hợp này, ta sẽ ko cần quan tâm đến hàm nào chạy ít hơn 1%.

Ta có kết quả:
Thread ID: 69883126035220

Fiber ID: 69883132260680

Total: 0.002094

Sort by: self_time

%selftotalselfwaitchildcallsname
17.370.0010.0000.0000.0013Kernel#gem_original_requi
16.970.0000.0000.0000.0002Regexp#match
10.850.0010.0000.0000.0001Class::Date#parse
2.360.0000.0000.0000.000113Module#method_added
1.830.0000.0000.0000.0006IO#set_encoding
1.570.0000.0000.0000.0001String#gsub!
1.230.0000.0000.0000.0006MonitorMixin#mon_enter
1.160.0020.0000.0000.0022Global#[Nomethod]
1.120.0000.0000.0000.0003Array#each
1.070.0000.0000.0000.00049BasicObject#singleton_met
1.030.0000.0000.0000.0006MonitorMixin#mon_exit

Với profile như trên, ta có thể theo dõi được lệnh nào mất nhiều thời gian nhất trong cả chương trình. Trong trường hợp này là Kernel#gem_original_require, chúng ta cũng có thể thấy thời gian dành cho lệnh require 'date'. Ngoài ra là các hàm khởi tạo instance, lớp cũng được xuất hiện. Cũng không ngạc nhiên, khi với một chương trình đơn giản như này thì thời gian cho việc khởi tạo khá nhiều so với các code cần thiết.

Với một profile được tạo ra bởi công cụ ruby-prof sẽ rất hữu ích nếu bạn quan tâm đến tối ưu chương trình khi khởi động và thời gian tải gem. Với những trường hợp khác, nó cũng thêm rất nhiều dữ liệu vào bản kết quả, và bạn nên sử dụng ruby-prof API hơn.

3. Rails Middleware

Ruby-prof API hoạt động tốt nhât khi bạn muốn tạo profile cho 1 phần của ứng dụng Rails, vd như controller action, hay thời gian render template. Nhưng nếu muốn tìm hiểu đến middleware, routing hay khởi tạo controller, bạn cần cài đặt ruby-prof như middleware.

Để làm điều này, cần thêm gem ruby-prof vào Gemfile:
gem 'ruby-prof'

Thêm bộ adapter Rack của ruby-prof vào middleware, trong config/application.rb

Hàm use sẽ thêm profiler vào bên dưới middleware stack. Vì vậy profile sẽ được thêm vào code khởi tạo Rails, nhưng bỏ qua middleware. Nếu bạn muốn profile middleware, thì cần thêm profiler trước Rack::Runtime.

Với Rack::RubyProf middleware được tải lên, bạn sẽ có kết quả báo cáo được lưu trong đường dẫn bạn cài đặt ở trên.

Đừng quên cần disable GC trước khi Rack::RubyProf bắt đầu. Cách tốt nhất để làm là viết một hay nhiều middleware và thêm vào trước profiler trong stack.

Trực quan hoá với Ruby-Prof Printer

Ruby-prof có thể tạo ra nhiều kiểu báo cáo dễ hiểu. Có 3 kiểu phổ biến nhất là flat, call graph và call stack. Mỗi loại sẽ có mục đích khác nhau. Chúng ta sẽ bắt đầu bằng chương trình phức tạp hơn để áp dụng với từng loại profiler:

Chương trình trên sẽ tạo random CSV với danh sách những người và bao gồm ngày sinh, xử lý nó và tìm ra người trẻ nhất từ danh sách. Ta sẽ in ra 3 bản báo cáo theo 3 loại trên. Và giới hạn để in các hàm mất nhiều hơn 3% tổng thời gian.

Flat report: Tìm các hàm chạy chậm

Flat profile sẽ hiển thị tổng thời gian mỗi hàm khi chạy. VD với chương trình trên ta có:

Thread ID: 70137029546800

Fiber ID: 70137039955760

Total: 1.882948

Sort by: self_time

%selftotalselfwaitchildcallsname
27.331.3540.5150.0000.839150000Object#parse_col
22.310.8060.4200.0000.38650000Class::Date#parse
8.590.1620.1620.0000.000100000Regexp#match
5.111.7070.0960.0001.61150000Object#parse_row
4.791.7970.0900.0001.70750002Array#map!
4.660.0880.0880.0000.00050001String#split
4.460.0840.0840.0000.00050000String#gsub!

Trong đó:

%self: là phần trăm trên tổng thời gian tiêu tốn cho hàm này.

total: là tổng thời gian mất cho hàm này, bao gồm thời gian thực thi của hàm khi được gọi.

self: là thời gian tiêu tốn cho hàm đó, không bao gồm thời gian thực thi khi nó gọi.

wait: là thời gian chờ các thread khác. Nó sẽ luôn là 0 với ứng dụng đơn thread.

child: là thời gian tiêu tốn trong các hàm được gọi từ hàm hiện tại

calls: là tổng số lời gọi đến hàm đó

Flat report được sắp xếp theo thời gian. Vì vậy các hàm ở trên cùng là hàm chạy tốn thời gian nhất.

Và giá trị self time trong báo cáo là tổng số thời gian chạy của tất cả lời gọi đến hàm đó, không phân biệt bất cứ lời gọi nào trong code. VD, hàm String#split được gọi trực tiếp từ parse_data và 50.000 lần trong vòng lặp parse_row. Trong báo cáo, ta thấy hàm String#split được gọi tất cả 50.001 lần.

Hãy lưu ý là self time không bao gồm thời gian các lời gọi hàm lồng nhau. VD, self time của Object#parse_col không gồm thời gian chạy tìm kiếm regular expresson hay quá trình biên dịch date. Mặc dù chỉ với một hàm đơn giản với chỉ một biểu thức if-else, Object#parse_col vẫn mất một khoảng thời gian đáng kể.

Ta đều biết, hàm trên cùng là chạy chậm nhất. Vì vậy cần tối ưu nó đầu tiên. Nhưng quá trình tối ưu hoá không dễ dàng. Nó không thể tối ưu hàm chậm nhất bằng self time, vì 2 lý do:

  • Profiler chỉ báo cáo một khoảng self time lớn cho một hàm thậm chí cả khi bạn tăng tốc nó.. VD, Object#parse_col không làm gì trong này. Tất cả là do thực thi biểu thức if-else..
  • Hàm chậm nhất có thể là một hàm thư viên hay đủ đơn giản để bạn không thể tối ưu. VD, Array#map là hàm chậm thứ 3. Nhưng nó là một thư viện và chúng ta không thể trực tiếp sửa.

Cả 2 trường hợp trên thực ra là do bởi số lời gọi hàm hơn là code trong hàm. Vì vậy, cách hiểu quả nhất để tối ưu là giảm bớt số lời gọi hàm. Và bạn cần biết hàm được gọi ở đâu và thường xuyên như nào. Nhưng trong báo cáo flat report không hiển thị điều đó. Vậy, bạn cần profile khác, đó là graph report – báo cáo đồ thị.

Graph report: Hiểu được những phần code nào chậm

Graph report được sắp xếp theo tổng số thời gian chạy hàm, bao gồm thời gian từ lúc gọi hàm.

Thread ID: 70137029546800

Fiber ID: 70137039955760

Total Time: 1.8829480049999994

Sort by: total_time

%selftotalselfwaitchildcallsname
100.00%0.01%1.8830.0001.8831Global#[No method]
1.7770.0001.7771/1Object#parse_data
0.1060.0000.1061/1Object#find_youngest
95.46%4.79%0.0000.0000.00050000/50002Object#parse_row
0.0310.0310.0001/50002Object#find_youngest
1.7670.0601.7071/50002Object#parse_data
1.7970.0901.70750002Array#map!
1.7070.0961.61150000/50000Object#parse_row
1.3540.5150.839150000/150000Object#parse_col
94.39%0.00%1.7770.0001.7771/1Global#[No method]
1.7770.0001.7771Object#parse_data
1.7670.0601.7071/50002Array#map!
0.0100.0100.0001/50001String#split
90.67%5.11%1.7070.0961.61150000/50000Array#map!
1.7070.0961.61150000Object#parse_row
0.0770.0770.00050000/50001String#split
0.0000.0000.00050000/50002Array#map!
71.88%27.33%1.3540.5150.839150000/150000Array#map!
1.3540.5150.839150000Object#parse_col
0.8060.4200.38650000/50000Class::Date#parse
0.0330.0330.00050000/50000String#to_i
42.79%22.31%0.8060.4200.38650000/50000Object#parse_col
0.8060.4200.38650000Class::Date#parse
0.1620.1620.000100000/100000Regexp#match
0.0840.0840.00050000/50000String#gsub!
0.0460.0460.00050000/50000String#[]=
0.0390.0390.00050000/50000MatchData#begin
0.0310.0310.00050000/50000Fixnum#div
0.0240.0240.00050000/50000MatchData#end
8.59%8.59%0.1620.1620.000100000/100000Class::Date#parse
0.1620.1620.000100000Regexp#match
5.61%0.00%0.1060.0000.1061/1Global#[No method]
0.1060.0000.1061Object#find_youngest
0.0750.0000.0751/1Enumerable#max
0.0310.0310.0001/50002Array#map!
4.66%4.66%0.0100.0100.0001/50001Object#parse_data
0.0770.0770.00050000/50001Object#parse_row
0.0880.0880.00050001String#split
4.46%4.46%0.0840.0840.00050000/50000Class::Date#parse
0.0840.0840.00050000String#gsub!
3.98%0.00%0.0750.0000.0751/1Object#find_youngest
0.0750.0000.0751Enumerable#max
0.0750.0350.0401/1Array#each
3.98%1.87%0.0750.0350.0401/1Enumerable#max
0.0750.0350.0401Array#each
0.0400.0400.00049999/49999Date#<=>

Ý nghĩa của các cột cũng tương tự như flat report. Nhưng với các lời gọi hàm ngay lập tức sẽ được để ở trên và những lời gọi được gọi thì sẽ để bên dưới.

Dòng thứ 2 là Array#map! yêu cầu nhiều nỗ lực hơn. Hàm chạy ở giữa, bởi vì bao gồm cả 3 lời gọi ở trên và 2 lời được gọi ở dưới.

Cột Calls hiển thị Array#map! 50.002 lần: 50.000 lần là từ Object#parse_now, một là từ Object#find_youngest, và một là từ Object#parse_data.

Cột timing cho lời gọi có nghĩa khác. Mỗi lời gọi sẽ hiển thị total, self và child mà Array#map! cần khi lời gọi được thực thi.

Thông tin hữu ích có từ bài report đó là thứ nhất, chúng ta có thể lấy được cái nhìn toàn cảnh tại nơi chương trình chạy. VD, chương trình chạy mất hầu như 90% thời gian dữ liệu xử lý các dòng CSV. Thứ hai, chúng ta có thể theo dấu profile từ trên xuống dưới để chỉ ra ý tưởng phần code nào chúng ta nên tối ưu. VD, chúng ta thấy được hàm chậm nhất thông qua tổng thời gian Array#map! gọi Object#parse_row. Đó là gọi String#split, có thời gian self time khá nhiều. Vì vậy có một cách để tối ưu đó là giảm số lượng lời gọi String#split hay thay thế chúng với hàm khác.

Chia sẻ bài viết ngay

Nguồn bài viết : Viblo