perlperf - Perl 效能與最佳化技巧
這是一份 perl 效能與最佳化技巧的入門介紹，特別針對 perl 程式使用。雖然許多 perl 開發人員來自其他語言，並能在適當的情況下運用他們的先備知識，但仍有許多人可能從一些 perl 特定的提示中受益。如果你想要濃縮版，或許最棒的建議來自於著名的日本武士宮本武藏，他在
"Do Not Engage in Useless Activity"1645 年說過。
程式設計師最常犯的錯誤，或許就是嘗試在程式實際執行任何有用的功能之前，就對其程式碼進行最佳化，這是一個壞主意。一個運作極快但無法運作的程式，一點意義也沒有。第一個工作是讓程式正確地執行某個有用的功能（更不用說確保測試套件完全運作），然後才考慮最佳化。在決定最佳化現有的工作程式碼時，有幾個簡單但必要的步驟需要考慮，這些步驟是任何最佳化流程中固有的。
首先，你需要為現有程式碼建立一個基準時間，而計時必須是可靠且可重複的。你可能需要使用 Benchmark 或 Devel::NYTProf 模組，或類似的東西，來執行此步驟，或者可能是 Unix 系統的 time 實用程式，以適當的為準。請參閱本文檔的底部，以取得更長的基準測試和剖析模組清單，以及建議的進一步閱讀資料。
接下來，在檢查程式是否有熱點（程式碼執行緩慢的地方）後，變更程式碼，目的是讓它執行得更快。使用版本控制軟體，例如 subversion，將確保沒有任何變更是不可逆的。在這裡和那裡進行調整很容易，不要一次變更太多，否則你可能無法找出哪一段程式碼才是真正的慢速部分。
光是說：「那樣會讓它執行得更快」是不夠的，你必須檢查它。從上述第一個步驟，在基準測試或剖析模組的控制下重新執行程式碼，並檢查新程式碼是否在更短的時間內執行相同的任務。儲存你的工作並重複...
在考慮效能時，最關鍵的事情是要記住，沒有所謂的「萬靈丹」，這就是為什麼沒有規則，只有準則。
很明顯地，內嵌程式碼會比子程式或方法呼叫快，因為它的開銷較小，但這種方法的缺點是可維護性較差，而且會以較大的記憶體使用量為代價，世上沒有免費的午餐。如果您要在清單中搜尋一個元素，將資料儲存在雜湊結構中會更有效率，然後只要查看金鑰是否已定義，而不是使用 grep() 逐一迴圈整個陣列。substr() 可能（會快很多）比 grep() 快，但靈活性較差，所以您必須在存取時權衡取捨。您的程式碼可能包含一行需要執行 0.01 秒，如果您呼叫它 1,000 次，很可能在一個程式中分析中等大小的檔案，您已經在單一程式碼位置產生 10 秒的延遲，如果您呼叫那行 100,000 次，您的整個程式將會慢到無法忍受。
將子程式用在您的排序中是一種取得您想要結果的有效方法，但通常會比內建的字母cmp和數字<=>排序運算子慢。您可以多次掃描您的資料，建立索引以提升即將進行的排序效率，並使用所謂的OM（半獸人策略）預先快取排序金鑰。快取查詢雖然是個好主意，但本身也可能成為減慢速度的來源，因為它會強制對資料進行兩次掃描，一次設定快取，一次排序資料。使用pack()將所需的排序金鑰萃取成一致的字串，可以成為建立單一字串用於比較，而不是使用多個排序金鑰的有效方法，這使得您可以在輸出上使用以c撰寫且快速的 Perl sort()函數，也是GRT（古特曼羅斯勒轉換）的基礎。有些字串組合會讓GRT變慢，因為它們對它來說實在太過複雜。
對於使用資料庫後端的應用程式，標準的 DBIx 名稱空間已嘗試協助保持事項的順暢，最重要的是它嘗試不查詢資料庫直到最後一刻，但務必閱讀隨附於您選擇的函式庫而來的文件。在處理資料庫時開發人員面臨的許多問題中，應始終注意使用 SQL 佔位符，並在可能有利時考慮預先擷取資料集。透過指定多個程序來解析單一檔案，例如使用 POE、threads 或 fork 分割大型檔案，也可以是最佳化使用可用 CPU 資源的有用方式，儘管此技術充滿並行問題，且需要高度注意細節。
每個案例都有特定的應用程式和一個或多個例外，而且沒有任何方法可以取代執行一些測試並找出最適合您特定環境的方法，這就是為什麼撰寫最佳化程式碼並非一門精確的科學，以及我們如此喜愛使用 Perl 的原因 - TMTOWTDI。
以下是幾個範例來說明 Perl 基準測試工具的使用方式。
我確定我們大多數人看過看起來像（或比）以下更糟的程式碼
if ( $obj->{_ref}->{_myscore} >= $obj->{_ref}->{_yourscore} ) {
...這類程式碼在閱讀時可能真的會令人討厭，而且對錯字非常敏感，且明確取消變數參考會更清楚。我們避開使用物件導向程式設計技術來封裝變數存取（僅可透過物件存取）的問題。我們在此僅討論技術實作的選擇，以及這是否會對效能造成影響。我們可以透過將比較程式碼放入檔案並執行 Benchmark 測試，來了解此取消參考操作是否有任何開銷。
# 取消參考
#!/usr/bin/perl
use v5.36;
use Benchmark;
my $ref = {
'ref' => {
_myscore => '100 + 1',
_yourscore => '102 - 1',
},
};
timethese(1000000, {
'direct' => sub {
my $x = $ref->{ref}->{_myscore} . $ref->{ref}->{_yourscore} ;
},
'dereference' => sub {
my $ref = $ref->{ref};
my $myscore = $ref->{_myscore};
my $yourscore = $ref->{_yourscore};
my $x = $myscore . $yourscore;
},
});執行任何計時測量時，執行次數必須足夠多，才能讓數字穩定在一個數值平均值上，否則每次執行都會因為環境變異而自然產生波動，例如，減少競爭CPU資源和網路頻寬的影響。針對上述程式碼執行一百萬次反覆運算，我們可以查看Benchmark模組的報告輸出，看看哪一種方法最有效。
$> perl dereference
Benchmark: timing 1000000 iterations of dereference, direct...
dereference: 2 wallclock secs ( 1.59 usr + 0.00 sys = 1.59 CPU) @ 628930.82/s (n=1000000)
direct: 1 wallclock secs ( 1.20 usr + 0.00 sys = 1.20 CPU) @ 833333.33/s (n=1000000)差異顯而易見，而取消參考的方法較慢。雖然在我們的測試中，它每秒平均執行 628,930 次，但很不幸地，直接方法每秒執行次數多出 204,403 次。很不幸地，因為有許多使用多層直接變數存取方式撰寫的程式碼範例，而且通常很糟糕。然而，它快了一點點。問題仍然是，這點微小的進步是否真的值得眼睛疲勞，或可維護性的損失。
如果我們有一個需要修改的字串，雖然正規表示式幾乎總是靈活許多，tr 這個經常未被充分利用的工具，仍然可能很有用。一個場景可能是將所有母音替換為另一個字元。正規表示式解法可能如下所示
$str =~ s/[aeiou]/x/gtr 的替代方法可能如下所示
$str =~ tr/aeiou/xxxxx/我們可以將其放入一個測試檔案中，執行以檢查哪一種方法最快，使用全域變數$STR指定給my $str變數，以避免 perl 透過注意到它只指定一次，而嘗試最佳化任何工作。
# regex-transliterate
#!/usr/bin/perl
use v5.36;
use Benchmark;
my $STR = "$$-this and that";
timethese( 1000000, {
'sr' => sub { my $str = $STR; $str =~ s/[aeiou]/x/g; return $str; },
'tr' => sub { my $str = $STR; $str =~ tr/aeiou/xxxxx/; return $str; },
});執行程式碼會給我們結果
$> perl regex-transliterate
Benchmark: timing 1000000 iterations of sr, tr...
sr: 2 wallclock secs ( 1.19 usr + 0.00 sys = 1.19 CPU) @ 840336.13/s (n=1000000)
tr: 0 wallclock secs ( 0.49 usr + 0.00 sys = 0.49 CPU) @ 2040816.33/s (n=1000000)tr 版本明顯獲勝。一種解法很靈活，另一種很快 - 而選擇使用哪一種，適當地由程式設計師決定。
查看Benchmark文件，以取得更多有用的技巧。
稍微大一點的程式碼片段，將提供剖析器可以產生更廣泛報告統計資料的內容。這個範例使用簡化的wordmatch程式，它會剖析給定的輸入檔案，並對內容噴出一個簡短報告。
# wordmatch
#!/usr/bin/perl
use v5.36;
=head1 NAME
filewords - word analysis of input file
=head1 SYNOPSIS
filewords -f inputfilename [-d]
=head1 DESCRIPTION
This program parses the given filename, specified with C<-f>, and
displays a simple analysis of the words found therein. Use the C<-d>
switch to enable debugging messages.
=cut
use FileHandle;
use Getopt::Long;
my $debug = 0;
my $file = '';
my $result = GetOptions (
'debug' => \$debug,
'file=s' => \$file,
);
die("invalid args") unless $result;
unless ( -f $file ) {
die("Usage: $0 -f filename [-d]");
}
my $FH = FileHandle->new("< $file")
or die("unable to open file($file): $!");
my $i_LINES = 0;
my $i_WORDS = 0;
my %count = ();
my @lines = <$FH>;
foreach my $line ( @lines ) {
$i_LINES++;
$line =~ s/\n//;
my @words = split(/ +/, $line);
my $i_words = scalar(@words);
$i_WORDS = $i_WORDS + $i_words;
debug("line: $i_LINES supplying $i_words words: @words");
my $i_word = 0;
foreach my $word ( @words ) {
$i_word++;
$count{$i_LINES}{spec} += matches($i_word, $word,
'[^a-zA-Z0-9]');
$count{$i_LINES}{only} += matches($i_word, $word,
'^[^a-zA-Z0-9]+$');
$count{$i_LINES}{cons} += matches($i_word, $word,
'^[(?i:bcdfghjklmnpqrstvwxyz)]+$');
$count{$i_LINES}{vows} += matches($i_word, $word,
'^[(?i:aeiou)]+$');
$count{$i_LINES}{caps} += matches($i_word, $word,
'^[(A-Z)]+$');
}
}
print report( %count );
sub matches {
my $i_wd = shift;
my $word = shift;
my $regex = shift;
my $has = 0;
if ( $word =~ /($regex)/ ) {
$has++ if $1;
}
debug( "word: $i_wd "
. ($has ? 'matches' : 'does not match')
. " chars: /$regex/");
return $has;
}
sub report {
my %report = @_;
my %rep;
foreach my $line ( keys %report ) {
foreach my $key ( keys $report{$line}->%* ) {
$rep{$key} += $report{$line}{$key};
}
}
my $report = qq|
$0 report for $file:
lines in file: $i_LINES
words in file: $i_WORDS
words with special (non-word) characters: $i_spec
words with only special (non-word) characters: $i_only
words with only consonants: $i_cons
words with only capital letters: $i_caps
words with only vowels: $i_vows
|;
return $report;
}
sub debug {
my $message = shift;
if ( $debug ) {
print STDERR "DBG: $message\n";
}
}
exit 0;此可敬的模組已成為 Perl 程式碼分析的實際標準超過十年，但已被其他許多模組取代，這些模組將我們帶回 21 世紀。儘管建議您從本文檔底部提到的幾個模組和 CPAN 清單中評估您的工具（目前 Devel::NYTProf 似乎是首選武器 - 請見下方），我們將先快速瀏覽 Devel::DProf 的輸出，以設定 Perl 分析工具的基準。使用命令列上的 -d 開關，在 Devel::DProf 的控制下執行上述程式。
$> perl -d:DProf wordmatch -f perl5db.pl
<...multiple lines snipped...>
wordmatch report for perl5db.pl:
lines in file: 9428
words in file: 50243
words with special (non-word) characters: 20480
words with only special (non-word) characters: 7790
words with only consonants: 4801
words with only capital letters: 1316
words with only vowels: 1701Devel::DProf 會產生一個特殊檔案，預設稱為 tmon.out，而此檔案會由 dprofpp 程式讀取，而此程式已安裝為 Devel::DProf 發行版的一部分。如果您在沒有任何選項的情況下呼叫 dprofpp，它會讀取目前目錄中的 tmon.out 檔案，並產生程式執行的人類可讀統計報告。請注意，這可能需要一點時間。
$> dprofpp
Total Elapsed Time = 2.951677 Seconds
User+System Time = 2.871677 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
102. 2.945 3.003 251215 0.0000 0.0000 main::matches
2.40 0.069 0.069 260643 0.0000 0.0000 main::debug
1.74 0.050 0.050 1 0.0500 0.0500 main::report
1.04 0.030 0.049 4 0.0075 0.0123 main::BEGIN
0.35 0.010 0.010 3 0.0033 0.0033 Exporter::as_heavy
0.35 0.010 0.010 7 0.0014 0.0014 IO::File::BEGIN
0.00 - -0.000 1 - - Getopt::Long::FindOption
0.00 - -0.000 1 - - Symbol::BEGIN
0.00 - -0.000 1 - - Fcntl::BEGIN
0.00 - -0.000 1 - - Fcntl::bootstrap
0.00 - -0.000 1 - - warnings::BEGIN
0.00 - -0.000 1 - - IO::bootstrap
0.00 - -0.000 1 - - Getopt::Long::ConfigDefaults
0.00 - -0.000 1 - - Getopt::Long::Configure
0.00 - -0.000 1 - - Symbol::gensymdprofpp 會產生一些關於 wordmatch 程式活動的詳細報告。分析頂端會顯示時鐘時間、使用者和系統時間，而其後的主欄定義了報告的定義。查看 dprofpp 文件，以取得其支援的許多選項的詳細資料。
另請參閱 Apache::DProf，它將 Devel::DProf 連結到 mod_perl。
讓我們使用不同的分析器來檢視同一個程式：Devel::Profiler，一個可直接取代 Devel::DProf 的 Perl 專用替換品。其用法略有不同，在於您不使用特殊的 -d: 旗標，而是使用 -M 將 Devel::Profiler 直接拉入作為模組。
$> perl -MDevel::Profiler wordmatch -f perl5db.pl
<...multiple lines snipped...>
wordmatch report for perl5db.pl:
lines in file: 9428
words in file: 50243
words with special (non-word) characters: 20480
words with only special (non-word) characters: 7790
words with only consonants: 4801
words with only capital letters: 1316
words with only vowels: 1701Devel::Profiler 會產生一個與 dprofpp 程式相容的 tmon.out 檔案，因此省去了建構專用統計讀取程式的步驟。因此，dprofpp 用法與上述範例相同。
$> dprofpp
Total Elapsed Time = 20.984 Seconds
User+System Time = 19.981 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
49.0 9.792 14.509 251215 0.0000 0.0001 main::matches
24.4 4.887 4.887 260643 0.0000 0.0000 main::debug
0.25 0.049 0.049 1 0.0490 0.0490 main::report
0.00 0.000 0.000 1 0.0000 0.0000 Getopt::Long::GetOptions
0.00 0.000 0.000 2 0.0000 0.0000 Getopt::Long::ParseOptionSpec
0.00 0.000 0.000 1 0.0000 0.0000 Getopt::Long::FindOption
0.00 0.000 0.000 1 0.0000 0.0000 IO::File::new
0.00 0.000 0.000 1 0.0000 0.0000 IO::Handle::new
0.00 0.000 0.000 1 0.0000 0.0000 Symbol::gensym
0.00 0.000 0.000 1 0.0000 0.0000 IO::File::open有趣的是，我們得到了略有不同的結果，這主要是因為產生報告的演算法不同，即使輸出檔案格式據稱相同。經過、使用者和系統時間清楚地顯示了Devel::Profiler執行其自執行所需的時間，但欄位清單感覺比我們之前從Devel::DProf獲得的清單更準確。例如，102% 的數字消失了。在使用工具之前，我們必須在此處使用我們可用的工具，並認識到它們的優缺點。有趣的是，兩個報告中每個子常式的呼叫次數相同，不同的部分是百分比。正如Devel::Profiler的作者所寫
...running HTML::Template's test suite under Devel::DProf shows
output() taking NO time but Devel::Profiler shows around 10% of the
time is in output(). I don't know which to trust but my gut tells me
something is wrong with Devel::DProf. HTML::Template::output() is a
big routine that's called for every test. Either way, something needs
fixing.YMMV。
另請參閱將Devel::Profiler掛接到mod_perl的Devel::Apache::Profiler。
Devel::SmallProf剖析器會檢查 Perl 程式執行時間，並產生逐行清單，以顯示呼叫每行的次數，以及執行每行所需的時間。它會透過在執行時提供熟悉的-d標記給 Perl 來呼叫。
$> perl -d:SmallProf wordmatch -f perl5db.pl
<...multiple lines snipped...>
wordmatch report for perl5db.pl:
lines in file: 9428
words in file: 50243
words with special (non-word) characters: 20480
words with only special (non-word) characters: 7790
words with only consonants: 4801
words with only capital letters: 1316
words with only vowels: 1701Devel::SmallProf會預設將其輸出寫入稱為smallprof.out的檔案。檔案格式如下所示
<num> <time> <ctime> <line>:<text>當程式終止時，可以使用任何標準文字過濾公用程式檢查和排序輸出。以下內容可能就夠了
$> cat smallprof.out | grep \d*: | sort -k3 | tac | head -n20
251215 1.65674 7.68000 75: if ( $word =~ /($regex)/ ) {
251215 0.03264 4.40000 79: debug("word: $i_wd ".($has ? 'matches' :
251215 0.02693 4.10000 81: return $has;
260643 0.02841 4.07000 128: if ( $debug ) {
260643 0.02601 4.04000 126: my $message = shift;
251215 0.02641 3.91000 73: my $has = 0;
251215 0.03311 3.71000 70: my $i_wd = shift;
251215 0.02699 3.69000 72: my $regex = shift;
251215 0.02766 3.68000 71: my $word = shift;
50243 0.59726 1.00000 59: $count{$i_LINES}{cons} =
50243 0.48175 0.92000 61: $count{$i_LINES}{spec} =
50243 0.00644 0.89000 56: my $i_cons = matches($i_word, $word,
50243 0.48837 0.88000 63: $count{$i_LINES}{caps} =
50243 0.00516 0.88000 58: my $i_caps = matches($i_word, $word, '^[(A-
50243 0.00631 0.81000 54: my $i_spec = matches($i_word, $word, '[^a-
50243 0.00496 0.80000 57: my $i_vows = matches($i_word, $word,
50243 0.00688 0.80000 53: $i_word++;
50243 0.48469 0.79000 62: $count{$i_LINES}{only} =
50243 0.48928 0.77000 60: $count{$i_LINES}{vows} =
50243 0.00683 0.75000 55: my $i_only = matches($i_word, $word, '^[^a-您可以立即看到子常式剖析模組略有不同的重點，我們開始看到哪一行程式碼花費最多時間。例如，那個正規表示式行看起來有點可疑。請記住，這些工具應該一起使用，沒有單一最佳方式來剖析您的程式碼，您需要使用最適合這項工作的工具。
另請參閱將Devel::SmallProf掛接到mod_perl的Apache::SmallProf。
Devel::FastProf是另一個 Perl 行剖析器。這是為了取得比例如Devel::SmallProf更快的行剖析器而編寫的，因為它是用C編寫的。若要使用Devel::FastProf，請提供-d引數給 Perl
$> perl -d:FastProf wordmatch -f perl5db.pl
<...multiple lines snipped...>
wordmatch report for perl5db.pl:
lines in file: 9428
words in file: 50243
words with special (non-word) characters: 20480
words with only special (non-word) characters: 7790
words with only consonants: 4801
words with only capital letters: 1316
words with only vowels: 1701Devel::FastProf會將統計資料寫入目前目錄中的fastprof.out檔案。輸出檔案（可以指定）可以使用fprofpp命令列程式來詮釋。
$> fprofpp | head -n20
# fprofpp output format is:
# filename:line time count: source
wordmatch:75 3.93338 251215: if ( $word =~ /($regex)/ ) {
wordmatch:79 1.77774 251215: debug("word: $i_wd ".($has ? 'matches' : 'does not match')." chars: /$regex/");
wordmatch:81 1.47604 251215: return $has;
wordmatch:126 1.43441 260643: my $message = shift;
wordmatch:128 1.42156 260643: if ( $debug ) {
wordmatch:70 1.36824 251215: my $i_wd = shift;
wordmatch:71 1.36739 251215: my $word = shift;
wordmatch:72 1.35939 251215: my $regex = shift;我們可以馬上看到，呼叫每一行的次數與 Devel::SmallProf 輸出相同，而且順序也僅根據執行每一行所花費的時間而略有不同，例如 if ( $debug ) { 和 my $message = shift;。實際記錄時間的差異可能在於內部使用的演算法，或者可能是因為系統資源限制或競爭。
另請參閱 DBIx::Profile，它將分析在 DBIx::* 名稱空間下執行的資料庫查詢。
Devel::NYTProf 是 新一代 Perl 程式碼分析器，它修正了其他工具的許多缺點，並實作許多很酷的功能。首先，它可以同時用作 行 分析器、區塊 或 子常式 分析器。它還可以在提供 clock_gettime() 的系統上使用次微秒 (100ns) 解析度。它甚至可以由正在分析的程式啟動和停止。它是一行輸入，用於分析 mod_perl 應用程式。它使用 c 編寫，可能是 Perl 中最快的分析器。很酷的功能清單還在持續增加。夠了，讓我們看看它是如何運作的 - 只需使用熟悉的 -d 開關將其插入並執行程式碼。
$> perl -d:NYTProf wordmatch -f perl5db.pl
wordmatch report for perl5db.pl:
lines in file: 9427
words in file: 50243
words with special (non-word) characters: 20480
words with only special (non-word) characters: 7790
words with only consonants: 4801
words with only capital letters: 1316
words with only vowels: 1701NYTProf 預設會在檔案 nytprof.out 中產生報告資料庫。可以使用提供的 nytprofhtml (HTML 輸出) 和 nytprofcsv (CSV 輸出) 程式從這裡產生人類可讀的報告。我們在此使用 Unix 系統 html2text 工具轉換 nytprof/index.html 檔案以方便使用。
$> html2text nytprof/index.html
Performance Profile Index
For wordmatch
Run on Fri Sep 26 13:46:39 2008
Reported on Fri Sep 26 13:47:23 2008
Top 15 Subroutines -- ordered by exclusive time
|Calls |P |F |Inclusive|Exclusive|Subroutine |
| | | |Time |Time | |
|251215|5 |1 |13.09263 |10.47692 |main:: |matches |
|260642|2 |1 |2.71199 |2.71199 |main:: |debug |
|1 |1 |1 |0.21404 |0.21404 |main:: |report |
|2 |2 |2 |0.00511 |0.00511 |XSLoader:: |load (xsub) |
|14 |14|7 |0.00304 |0.00298 |Exporter:: |import |
|3 |1 |1 |0.00265 |0.00254 |Exporter:: |as_heavy |
|10 |10|4 |0.00140 |0.00140 |vars:: |import |
|13 |13|1 |0.00129 |0.00109 |constant:: |import |
|1 |1 |1 |0.00360 |0.00096 |FileHandle:: |import |
|3 |3 |3 |0.00086 |0.00074 |warnings::register::|import |
|9 |3 |1 |0.00036 |0.00036 |strict:: |bits |
|13 |13|13|0.00032 |0.00029 |strict:: |import |
|2 |2 |2 |0.00020 |0.00020 |warnings:: |import |
|2 |1 |1 |0.00020 |0.00020 |Getopt::Long:: |ParseOptionSpec|
|7 |7 |6 |0.00043 |0.00020 |strict:: |unimport |
For more information see the full list of 189 subroutines.報告的第一部分已經顯示了有關哪些子常式使用最多時間的重要資訊。下一部分提供了一些關於分析的原始檔的統計資料。
Source Code Files -- ordered by exclusive time then name
|Stmts |Exclusive|Avg. |Reports |Source File |
| |Time | | | |
|2699761|15.66654 |6e-06 |line . block . sub|wordmatch |
|35 |0.02187 |0.00062|line . block . sub|IO/Handle.pm |
|274 |0.01525 |0.00006|line . block . sub|Getopt/Long.pm |
|20 |0.00585 |0.00029|line . block . sub|Fcntl.pm |
|128 |0.00340 |0.00003|line . block . sub|Exporter/Heavy.pm |
|42 |0.00332 |0.00008|line . block . sub|IO/File.pm |
|261 |0.00308 |0.00001|line . block . sub|Exporter.pm |
|323 |0.00248 |8e-06 |line . block . sub|constant.pm |
|12 |0.00246 |0.00021|line . block . sub|File/Spec/Unix.pm |
|191 |0.00240 |0.00001|line . block . sub|vars.pm |
|77 |0.00201 |0.00003|line . block . sub|FileHandle.pm |
|12 |0.00198 |0.00016|line . block . sub|Carp.pm |
|14 |0.00175 |0.00013|line . block . sub|Symbol.pm |
|15 |0.00130 |0.00009|line . block . sub|IO.pm |
|22 |0.00120 |0.00005|line . block . sub|IO/Seekable.pm |
|198 |0.00085 |4e-06 |line . block . sub|warnings/register.pm|
|114 |0.00080 |7e-06 |line . block . sub|strict.pm |
|47 |0.00068 |0.00001|line . block . sub|warnings.pm |
|27 |0.00054 |0.00002|line . block . sub|overload.pm |
|9 |0.00047 |0.00005|line . block . sub|SelectSaver.pm |
|13 |0.00045 |0.00003|line . block . sub|File/Spec.pm |
|2701595|15.73869 | |Total |
|128647 |0.74946 | |Average |
| |0.00201 |0.00003|Median |
| |0.00121 |0.00003|Deviation |
Report produced by the NYTProf 2.03 Perl profiler, developed by Tim Bunce and
Adam Kaplan.在這個時候，如果您正在使用 html 報告，您可以按一下各種連結深入探討每個子常式和每一行程式碼。由於我們在此使用文字報告，而且有一個完整的目錄包含為每個原始檔建立的報告，我們將只顯示對應的 wordmatch-line.html 檔案的一部分，足以讓您了解這個很酷的工具可以預期的輸出類型。
$> html2text nytprof/wordmatch-line.html
Performance Profile -- -block view-.-line view-.-sub view-
For wordmatch
Run on Fri Sep 26 13:46:39 2008
Reported on Fri Sep 26 13:47:22 2008
File wordmatch
Subroutines -- ordered by exclusive time
|Calls |P|F|Inclusive|Exclusive|Subroutine |
| | | |Time |Time | |
|251215|5|1|13.09263 |10.47692 |main::|matches|
|260642|2|1|2.71199 |2.71199 |main::|debug |
|1 |1|1|0.21404 |0.21404 |main::|report |
|0 |0|0|0 |0 |main::|BEGIN |
|Line|Stmts.|Exclusive|Avg. |Code |
| | |Time | | |
|1 | | | |#!/usr/bin/perl |
|2 | | | | |
| | | | |use strict; |
|3 |3 |0.00086 |0.00029|# spent 0.00003s making 1 calls to strict:: |
| | | | |import |
| | | | |use warnings; |
|4 |3 |0.01563 |0.00521|# spent 0.00012s making 1 calls to warnings:: |
| | | | |import |
|5 | | | | |
|6 | | | |=head1 NAME |
|7 | | | | |
|8 | | | |filewords - word analysis of input file |
<...snip...>
|62 |1 |0.00445 |0.00445|print report( %count ); |
| | | | |# spent 0.21404s making 1 calls to main::report|
|63 | | | | |
| | | | |# spent 23.56955s (10.47692+2.61571) within |
| | | | |main::matches which was called 251215 times, |
| | | | |avg 0.00005s/call: # 50243 times |
| | | | |(2.12134+0.51939s) at line 57 of wordmatch, avg|
| | | | |0.00005s/call # 50243 times (2.17735+0.54550s) |
|64 | | | |at line 56 of wordmatch, avg 0.00005s/call # |
| | | | |50243 times (2.10992+0.51797s) at line 58 of |
| | | | |wordmatch, avg 0.00005s/call # 50243 times |
| | | | |(2.12696+0.51598s) at line 55 of wordmatch, avg|
| | | | |0.00005s/call # 50243 times (1.94134+0.51687s) |
| | | | |at line 54 of wordmatch, avg 0.00005s/call |
| | | | |sub matches { |
<...snip...>
|102 | | | | |
| | | | |# spent 2.71199s within main::debug which was |
| | | | |called 260642 times, avg 0.00001s/call: # |
| | | | |251215 times (2.61571+0s) by main::matches at |
|103 | | | |line 74 of wordmatch, avg 0.00001s/call # 9427 |
| | | | |times (0.09628+0s) at line 50 of wordmatch, avg|
| | | | |0.00001s/call |
| | | | |sub debug { |
|104 |260642|0.58496 |2e-06 |my $message = shift; |
|105 | | | | |
|106 |260642|1.09917 |4e-06 |if ( $debug ) { |
|107 | | | |print STDERR "DBG: $message\n"; |
|108 | | | |} |
|109 | | | |} |
|110 | | | | |
|111 |1 |0.01501 |0.01501|exit 0; |
|112 | | | | |裡面有大量的有用資訊 - 這似乎是前進的方向。
另請參閱 Devel::NYTProf::Apache，它將 Devel::NYTProf 連結到 mod_perl。
Perl 模組並非效能分析師唯一可用的工具，不應忽略系統工具，例如 time，如下一個範例所示，我們快速檢視排序。許多書籍、論文和文章都撰寫過關於有效率的排序演算法，這裡並非重複這些工作的場合，有幾個不錯的排序模組也值得一試：Sort::Maker、Sort::Key 浮現在腦海中。不過，仍然可以針對某些 Perl 特定詮釋來觀察與排序資料集相關的問題，並提供一或兩個範例，說明如何排序大型資料量會影響效能。首先，在排序大量資料時，一個常被忽略的重點是，可以嘗試縮減要處理的資料集，在許多情況下，grep() 可以作為一個簡單的篩選器，相當有用
@data = sort grep { /$filter/ } @incoming像這樣的指令可以大幅縮減實際上要排序的資料量，不應僅僅因為其簡單性就輕易忽略。KISS 原則常常被忽略 - 下一個範例使用簡單的系統 time 工具來示範。我們來看看一個實際範例，排序大型檔案的內容，一個 apache 日誌檔就可以了。這個檔案有超過 25 萬行，大小為 50M，其中一個片段如下所示
# 日誌檔
188.209-65-87.adsl-dyn.isp.belgacom.be - - [08/Feb/2007:12:57:16 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
188.209-65-87.adsl-dyn.isp.belgacom.be - - [08/Feb/2007:12:57:16 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
151.56.71.198 - - [08/Feb/2007:12:57:41 +0000] "GET /suse-on-vaio.html HTTP/1.1" 200 2858 "http://www.linux-on-laptops.com/sony.html" "Mozilla/5.0 (Windows; U; Windows NT 5.2; en-US; rv:1.8.1.1) Gecko/20061204 Firefox/2.0.0.1"
151.56.71.198 - - [08/Feb/2007:12:57:42 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/suse-on-vaio.html" "Mozilla/5.0 (Windows; U; Windows NT 5.2; en-US; rv:1.8.1.1) Gecko/20061204 Firefox/2.0.0.1"
151.56.71.198 - - [08/Feb/2007:12:57:43 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.2; en-US; rv:1.8.1.1) Gecko/20061204 Firefox/2.0.0.1"
217.113.68.60 - - [08/Feb/2007:13:02:15 +0000] "GET / HTTP/1.1" 304 - "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
217.113.68.60 - - [08/Feb/2007:13:02:16 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
debora.to.isac.cnr.it - - [08/Feb/2007:13:03:58 +0000] "GET /suse-on-vaio.html HTTP/1.1" 200 2858 "http://www.linux-on-laptops.com/sony.html" "Mozilla/5.0 (compatible; Konqueror/3.4; Linux) KHTML/3.4.0 (like Gecko)"
debora.to.isac.cnr.it - - [08/Feb/2007:13:03:58 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/suse-on-vaio.html" "Mozilla/5.0 (compatible; Konqueror/3.4; Linux) KHTML/3.4.0 (like Gecko)"
debora.to.isac.cnr.it - - [08/Feb/2007:13:03:58 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/5.0 (compatible; Konqueror/3.4; Linux) KHTML/3.4.0 (like Gecko)"
195.24.196.99 - - [08/Feb/2007:13:26:48 +0000] "GET / HTTP/1.0" 200 3309 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.8.0.9) Gecko/20061206 Firefox/1.5.0.9"
195.24.196.99 - - [08/Feb/2007:13:26:58 +0000] "GET /data/css HTTP/1.0" 404 206 "http://www.rfi.net/" "Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.8.0.9) Gecko/20061206 Firefox/1.5.0.9"
195.24.196.99 - - [08/Feb/2007:13:26:59 +0000] "GET /favicon.ico HTTP/1.0" 404 209 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.8.0.9) Gecko/20061206 Firefox/1.5.0.9"
crawl1.cosmixcorp.com - - [08/Feb/2007:13:27:57 +0000] "GET /robots.txt HTTP/1.0" 200 179 "-" "voyager/1.0"
crawl1.cosmixcorp.com - - [08/Feb/2007:13:28:25 +0000] "GET /links.html HTTP/1.0" 200 3413 "-" "voyager/1.0"
fhm226.internetdsl.tpnet.pl - - [08/Feb/2007:13:37:32 +0000] "GET /suse-on-vaio.html HTTP/1.1" 200 2858 "http://www.linux-on-laptops.com/sony.html" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
fhm226.internetdsl.tpnet.pl - - [08/Feb/2007:13:37:34 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/suse-on-vaio.html" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
80.247.140.134 - - [08/Feb/2007:13:57:35 +0000] "GET / HTTP/1.1" 200 3309 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; .NET CLR 1.1.4322)"
80.247.140.134 - - [08/Feb/2007:13:57:37 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; .NET CLR 1.1.4322)"
pop.compuscan.co.za - - [08/Feb/2007:14:10:43 +0000] "GET / HTTP/1.1" 200 3309 "-" "www.clamav.net"
livebot-207-46-98-57.search.live.com - - [08/Feb/2007:14:12:04 +0000] "GET /robots.txt HTTP/1.0" 200 179 "-" "msnbot/1.0 (+http://search.msn.com/msnbot.htm)"
livebot-207-46-98-57.search.live.com - - [08/Feb/2007:14:12:04 +0000] "GET /html/oracle.html HTTP/1.0" 404 214 "-" "msnbot/1.0 (+http://search.msn.com/msnbot.htm)"
dslb-088-064-005-154.pools.arcor-ip.net - - [08/Feb/2007:14:12:15 +0000] "GET / HTTP/1.1" 200 3309 "-" "www.clamav.net"
196.201.92.41 - - [08/Feb/2007:14:15:01 +0000] "GET / HTTP/1.1" 200 3309 "-" "MOT-L7/08.B7.DCR MIB/2.2.1 Profile/MIDP-2.0 Configuration/CLDC-1.1"這裡的特定任務是根據回應代碼、查詢、瀏覽器、參考網址，最後是日期，來排序這個檔案的 286,525 行。一種可能的解決方案是使用以下程式碼，它會反覆處理命令列中指定的檔案。
# sort-apache-log
#!/usr/bin/perl -n
use v5.36;
my @data;
LINE:
while ( <> ) {
my $line = $_;
if (
$line =~ m/^(
([\w\.\-]+) # client
\s*-\s*-\s*\[
([^]]+) # date
\]\s*"\w+\s*
(\S+) # query
[^"]+"\s*
(\d+) # status
\s+\S+\s+"[^"]*"\s+"
([^"]*) # browser
"
.*
)$/x
) {
my @chunks = split(/ +/, $line);
my $ip = $1;
my $date = $2;
my $query = $3;
my $status = $4;
my $browser = $5;
push(@data, [$ip, $date, $query, $status, $browser, $line]);
}
}
my @sorted = sort {
$a->[3] cmp $b->[3]
||
$a->[2] cmp $b->[2]
||
$a->[0] cmp $b->[0]
||
$a->[1] cmp $b->[1]
||
$a->[4] cmp $b->[4]
} @data;
foreach my $data ( @sorted ) {
print $data->[5];
}
exit 0;在執行這個程式時，重新導向 STDOUT，這樣就可以從後續的測試執行中檢查輸出是否正確，並使用系統 time 工具來檢查整體執行時間。
$> time ./sort-apache-log logfile > out-sort
real 0m17.371s
user 0m15.757s
sys 0m0.592s這程式執行時間僅超過 17 個時鐘秒。請注意 time 輸出的不同值，務必始終使用相同的值，且不要混淆每個值的意思。
time 被呼叫與終止之間的總計或時鐘時間。經過時間包含使用者時間和系統時間，以及等待系統上其他使用者和處理程序的時間。這無可避免地是所提供測量中最近似的。
使用者時間是整個處理程序代表使用者在此系統上執行此程式所花費的時間。
系統時間是核心本身代表此處理程序使用者執行例程或系統呼叫所花費的時間。
將此相同處理程序作為 Schwarzian Transform 執行，可以消除用於儲存所有資料的輸入和輸出陣列，並在輸入時直接處理輸入。否則，程式碼看起來相當類似
# sort-apache-log-schwarzian
#!/usr/bin/perl -n
use v5.36;
print
map $_->[0] =>
sort {
$a->[4] cmp $b->[4]
||
$a->[3] cmp $b->[3]
||
$a->[1] cmp $b->[1]
||
$a->[2] cmp $b->[2]
||
$a->[5] cmp $b->[5]
}
map [ $_, m/^(
([\w\.\-]+) # client
\s*-\s*-\s*\[
([^]]+) # date
\]\s*"\w+\s*
(\S+) # query
[^"]+"\s*
(\d+) # status
\s+\S+\s+"[^"]*"\s+"
([^"]*) # browser
"
.*
)$/xo ]
=> <>;
exit 0;針對相同的日誌檔執行新程式碼，如上所述，以檢查新時間。
$> time ./sort-apache-log-schwarzian logfile > out-schwarz
real 0m9.664s
user 0m8.873s
sys 0m0.704s時間已減半，這是任何標準下的可觀速度提升。自然地，重要的是檢查輸出是否與第一次執行的程式一致，這就是 Unix 系統 cksum 程式發揮作用的地方。
$> cksum out-sort out-schwarz
3044173777 52029194 out-sort
3044173777 52029194 out-schwarz順帶一提。也要小心經理的壓力，他們看到您一次將程式執行時間提升 50%，只在一個月後收到再次這樣做的請求（真實故事） - 您只需要指出您只是人類，即使您是 Perl 程式設計師，您也會看看您能做什麼...
任何良好開發流程的必要部分都是適當的錯誤處理以及適當地提供資訊性訊息，然而有一派思想認為日誌檔應該是健談的，彷彿一連串不間斷的輸出在某種程度上確保了程式的存續。如果速度有任何問題，這種方法是錯誤的。
常見的景象是看起來像這樣的程式碼
logger->debug( "A logging message via process-id: $$ INC: "
. Dumper(\%INC) )問題在於，即使記錄組態檔中設定的偵錯層級為零，此程式碼仍會始終被解析和執行。例如，一旦進入 debug() 子例程，並確認內部 $debug 變數為零，則傳送進來的訊息將會被捨棄，而程式將會繼續執行。然而，在給定的範例中，\%INC hash 已經被傾印，訊息字串已經建構，所有這些工作都可以透過像這樣在陳述層級的偵錯變數來略過
logger->debug( "A logging message via process-id: $$ INC: "
. Dumper(\%INC) ) if $DEBUG;可以透過設定包含兩種形式的測試腳本來展示此效果，包括一個 debug() 子例程來模擬典型的 logger() 功能。
# ifdebug
#!/usr/bin/perl
use v5.36;
use Benchmark;
use Data::Dumper;
my $DEBUG = 0;
sub debug {
my $msg = shift;
if ( $DEBUG ) {
print "DEBUG: $msg\n";
}
};
timethese(100000, {
'debug' => sub {
debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) )
},
'ifdebug' => sub {
debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if $DEBUG
},
});讓我們看看 Benchmark 如何處理這件事
$> perl ifdebug
Benchmark: timing 100000 iterations of constant, sub...
ifdebug: 0 wallclock secs ( 0.01 usr + 0.00 sys = 0.01 CPU) @ 10000000.00/s (n=100000)
(warning: too few iterations for a reliable count)
debug: 14 wallclock secs (13.18 usr + 0.04 sys = 13.22 CPU) @ 7564.30/s (n=100000)在一個情況下，就輸出除錯資訊而言，程式碼與其他情況下完全相同，換句話說，什麼都沒有，需要 14 秒，而在另一種情況下，程式碼需要十分之一秒。看起來相當明確。在呼叫子常式之前使用 $DEBUG 變數，而不是依賴其內部的智慧功能。
透過使用編譯時間 DEBUG 常數，可以將前一個想法再進一步。
# ifdebug-constant
#!/usr/bin/perl
use v5.36;
use Benchmark;
use Data::Dumper;
use constant
DEBUG => 0
;
sub debug {
if ( DEBUG ) {
my $msg = shift;
print "DEBUG: $msg\n";
}
};
timethese(100000, {
'debug' => sub {
debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) )
},
'constant' => sub {
debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if DEBUG
},
});執行這個程式會產生下列輸出
$> perl ifdebug-constant
Benchmark: timing 100000 iterations of constant, sub...
constant: 0 wallclock secs (-0.00 usr + 0.00 sys = -0.00 CPU) @ -7205759403792793600000.00/s (n=100000)
(warning: too few iterations for a reliable count)
sub: 14 wallclock secs (13.09 usr + 0.00 sys = 13.09 CPU) @ 7639.42/s (n=100000)DEBUG 常數甚至比 $debug 變數更厲害，以負零秒計時，並產生「警告：反覆運算次數太少，無法進行可靠的計算」訊息。為了查看實際發生了什麼事，以及為什麼當我們認為要求 100000 次反覆運算時，卻只有太少的反覆運算，我們可以使用非常有用的 B::Deparse 來檢查新程式碼
$> perl -MO=Deparse ifdebug-constant
use Benchmark;
use Data::Dumper;
use constant ('DEBUG', 0);
sub debug {
use warnings;
use strict 'refs';
0;
}
use warnings;
use strict 'refs';
timethese(100000, {'sub', sub {
debug "A $0 logging message via process-id: $$" . Dumper(\%INC);
}
, 'constant', sub {
0;
}
});
ifdebug-constant syntax OK輸出顯示我們正在測試的 constant() 子常式被替換為 DEBUG 常數的值：零。要測試的行已完全最佳化，而且你無法獲得比這更高的效率。
本文提供了多種方法來識別熱點，並檢查任何修改是否改善了程式碼的執行時間。
最後一個想法，請記住，在撰寫本文時，不可能產生一個在零或負時間內執行的有用程式，而這個基本原則可以寫成：根據定義，有用的程式很慢。當然有可能寫一個幾乎立即執行的程式，但它不會做太多事情，以下是一個非常有效率的程式
$> perl -e 0進一步最佳化是 p5p 的工作。
可以使用下列模組和連結找到進一步的閱讀資料。
例如：perldoc -f sort。
perlfork、perlfunc、perlretut、perlthrtut。
執行緒.
時間.
顯然地，不可能在這裡個別展示所有與 Perl 相關的效能程式碼，但這裡列出一些值得進一步關注的 CPAN 模組。
Apache::DProf
Apache::SmallProf
Benchmark
DBIx::Profile
Devel::AutoProfiler
Devel::DProf
Devel::DProfLB
Devel::FastProf
Devel::GraphVizProf
Devel::NYTProf
Devel::NYTProf::Apache
Devel::Profiler
Devel::Profile
Devel::Profit
Devel::SmallProf
Devel::WxProf
POE::Devel::Profiler
Sort::Key
Sort::Maker非常有用的線上參考文件
https://web.archive.org/web/20120515021937/http://www.ccl4.org/~nick/P/Fast_Enough/
https://web.archive.org/web/20050706081718/http://www-106.ibm.com/developerworks/library/l-optperl.html
https://perlbuzz.com/2007/11/14/bind_output_variables_in_dbi_for_speed_and_safety/
http://en.wikipedia.org/wiki/Performance_analysis
http://apache.perl.org/docs/1.0/guide/performance.html
http://perlgolf.sourceforge.net/
http://www.sysarch.com/Perl/sort_paper.htmlRichard Foley <richard.foley@rfi.net> 版權所有 (c) 2008