Perl 성능과 최적화 기법
Perl 성능과 최적화 기법 (perlperf)
Perl 프로그램에 특히 유용하게 쓸 수 있는 성능·최적화 기법을 소개하는 문서예요. 압축 버전을 원하신다면, 유명한 일본 사무라이 미야모토 무사시가 1645년에 남긴 말이 최고의 조언일 거예요:
"쓸모없는 활동에 몸담지 말라 (Do Not Engage in Useless Activity)"
본문
개요 (OVERVIEW)
프로그래머가 저지르는 가장 흔한 실수는 프로그램이 실제로 유용한 일을 하기 전에 코드를 최적화하려고 시도하는 거예요. 이건 나쁜 생각이에요. 동작하지 않는 엄청나게 빠른 프로그램을 갖는 건 아무 의미가 없으니까요. 첫 번째 임무는 프로그램이 정확하게 무언가 유용한 일을 하게 만드는 거예요. (테스트 스위트가 완전히 동작하는지 확인하는 건 말할 것도 없고요.) 그래야만 비로소 최적화를 고려할 수 있어요. 기존의 동작하는 코드를 최적화하기로 결정했다면, 어떤 최적화 과정에든 본질적으로 필요한 몇 가지 단순하지만 필수적인 단계를 고려해야 해요.
한 걸음 옆으로 (ONE STEP SIDEWAYS)
먼저 기존 코드의 기준 시간(baseline time)을 확립해야 해요. 그 타이밍은 신뢰할 수 있고 반복 가능해야 해요. 이 단계에서는 Benchmark나 Devel::NYTProf 모듈, 비슷한 것, 또는 Unix 시스템 time 유틸리티를 쓰는 게 좋을 거예요. 어느 쪽이 적절하든요. 이 문서의 하단에는 벤치마킹·프로파일링 모듈의 더 긴 목록과 추천 추가 자료가 있어요.
한 걸음 앞으로 (ONE STEP FORWARD)
다음으로 프로그램에서 핫 스팟(코드가 느리게 실행되는 것처럼 보이는 곳)을 살펴본 뒤, 더 빨리 실행되도록 코드를 바꿔요. subversion 같은 버전 관리 소프트웨어를 쓰면 어떤 변경도 되돌릴 수 없게 되지 않아요. 여기저기 만지작거리기 너무 쉬워요. 한 번에 너무 많이 바꾸지 마세요. 그래야 어떤 코드 조각이 정말로 느린 부분이었는지 알아낼 수 있으니까요.
또 한 걸음 옆으로 (ANOTHER STEP SIDEWAYS)
"그러면 더 빨라질 거야"라고 말하는 것만으로는 부족해요. 확인해야 해요. 위 첫 단계의 벤치마킹·프로파일링 모듈 통제 아래 코드를 다시 실행하고, 새 코드가 같은 작업을 더 짧은 시간에 실행했는지 확인해요. 작업을 저장하고 반복하세요...
일반 지침 (GENERAL GUIDELINES)
성능을 고려할 때 가장 중요한 것은 Golden Bullet(금탄) 같은 건 없다는 걸 기억하는 거예요. 그래서 규칙이 아니라 지침만 있는 거죠.
인라인 코드는 오버헤드가 적으므로 서브루틴이나 메서드 호출보다 빠를 게 분명해요. 하지만 이 접근에는 유지보수성이 떨어지고 메모리 사용량이 더 크다는 단점이 있어요. 공짜 점심 같은 건 없으니까요. 리스트에서 요소를 찾고 있다면, 예를 들어 grep()으로 전체 배열을 순회하는 것보다 데이터를 해시 구조에 저장해 키가 정의됐는지만 보는 게 더 효율적일 수 있어요. substr()은 grep()보다 (훨씬) 빠를 수 있지만 유연하지 않아요. 그래서 또 다른 트레이드오프를 접하게 돼요. 코드에 실행에 0.01초가 걸리는 줄이 있을 수 있어요. 그걸 1,000번 호출하면(중간 크기 파일을 파싱하는 프로그램에서 아주 흔하죠) 단 하나의 코드 위치에서 이미 10초 지연이 생겨요. 그 줄을 100,000번 호출하면 프로그램 전체가 참을 수 없는 기어가기로 느려질 거예요.
sort의 일부로 서브루틴을 쓰는 건 정확히 원하는 것을 얻는 강력한 방법이지만, 보통 내장 알파벳 cmp와 숫자 <=> 정렬 연산자보다 느려요. 데이터에 여러 번 패스를 만들어 다가올 정렬을 더 효율적으로 하기 위한 인덱스를 만들고, OM(Orcish Maneuver)이라 불리는 것으로 정렬 키를 미리 캐시할 수 있어요. 캐시 조회는 좋은 생각이지만, 데이터를 두 번 패스하게 강제함으로써(한 번은 캐시 설정, 한 번은 데이터 정렬) 느려짐의 원인이 될 수도 있어요. pack()으로 필요한 정렬 키를 일관된 문자열로 추출하는 건, 여러 정렬 키를 쓰는 대신 비교할 단일 문자열을 만드는 효율적인 방법이 될 수 있어요. 그래서 c로 작성된 표준적이고 빠른 perl sort() 함수를 출력에 쓸 수 있고, 이게 GRT(Guttman Rossler Transform)의 기반이 돼요. 어떤 문자열 조합은 스스로 너무 복잡해서 GRT를 느리게 할 수도 있어요.
데이터베이스 백엔드를 쓰는 응용에서는 표준 DBIx 네임스페이스가 빠르게 유지하도록 도우려 했어요. 가능한 마지막 순간까지 데이터베이스를 조회하지 않으려 하기 때문이죠. 하지만 항상 선택한 라이브러리와 함께 오는 문서를 읽어야 해요. 데이터베이스를 다루는 개발자가 직면하는 많은 문제 중 알아둬야 할 것은 항상 SQL 플레이스홀더를 쓰고, 유리할 수 있으면 데이터 셋을 미리 가져오는 것(pre-fetching)을 고려하는 거예요. POE, threads, fork를 써서 여러 프로세스를 단일 파일 파싱에 배정해 큰 파일을 쪼개는 것도 가용 CPU 자원 사용을 최적화하는 유용한 방법일 수 있어요. 다만 이 기법은 동시성 문제가 가득하고 높은 세심함을 요구해요.
모든 경우에는 특정 응용과 하나 이상의 예외가 있고, 몇 가지 테스트를 실행해 특정 환경에 어떤 방법이 가장 잘 맞는지 알아내는 걸 대체할 수는 없어요. 그게 최적 코드 작성이 정확한 과학이 아닌 이유이고, 우리가 Perl을 그토록 사랑하는 이유예요 - TMTOWTDI (There's More Than One Way To Do It, 방법은 하나가 아니야).
벤치마크 (BENCHMARKS)
Perl의 벤치마킹 도구 사용을 보여주는 몇 가지 예시예요.
변수 할당과 역참조 (Assigning and Dereferencing Variables)
우리 대부분은 (더 나쁜) 이런 코드를 봤을 거예요:
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 (Search and replace or tr)
수정할 필요가 있는 문자열이 있다면, 정규식이 거의 항상 훨씬 유연하지만 가끔 과소평가되는 도구 tr도 여전히 유용할 수 있어요. 한 시나리오는 모든 모음을 다른 문자로 바꾸는 거예요. 정규식 해법은 이렇게 생겼어요:
$str =~ s/[aeiou]/x/g
tr 대안은 이렇게 생겼어요:
$str =~ tr/aeiou/xxxxx/
이걸 테스트 파일에 넣고 어떤 접근이 가장 빠른지 확인할 수 있어요. my $str 변수에 할당할 전역 $STR 변수를 써서, perl이 한 번만 할당된다는 걸 알아차리고 작업 중 일부를 최적화해버리는 것을 피할게요.
#!/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 문서를 확인하세요.
프로파일링 도구 (PROFILING TOOLS)
조금 더 큰 코드 조각이 프로파일러가 더 광범위한 통계 리포팅을 만들 무언가를 제공할 거예요. 이 예시는 주어진 입력 파일을 파싱하고 내용에 대한 짧은 리포트를 뱉는 단순한 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;
Devel::DProf
이 유서 깊은 모듈은 10년 넘게 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: 1701
Devel::DProf는 기본적으로 tmon.out 이라는 특수 파일을 만들고, 이 파일을 Devel::DProf 배포의 일부로 이미 설치된 dprofpp 프로그램이 읽어요. 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::gensym
dprofpp는 wordmatch 프로그램의 활동에 대한 꽤 상세한 리포트를 만들어요. wallclock, user, system 시간이 분석의 맨 위에 있고, 그 뒤에 리포트를 정의하는 주요 열들이 나와요. 지원하는 많은 옵션의 자세한 내용은 dprofpp 문서를 확인하세요.
Devel::DProf를 mod_perl에 연결하는 [Apache::DProf](https://metacpan.org/pod/Apache::DProf)도 참고하세요.
Devel::Profiler
다른 프로파일러로 같은 프로그램을 살펴볼게요. 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: 1701
Devel::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
흥미롭게도 약간 다른 결과를 얻어요. 출력 파일 형식이 동일하다고 주장됐는데도 리포트를 만드는 알고리즘이 다르기 때문이 대부분이에요. 경과, user, system 시간은 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](https://metacpan.org/pod/Devel::Apache::Profiler)도 참고하세요.
Devel::SmallProf
Devel::SmallProf 프로파일러는 Perl 프로그램의 런타임을 조사해, 각 줄이 몇 번 호출됐고 각 줄을 실행하는 데 얼마나 걸렸는지 보여주는 줄별 목록을 만들어요. 실행 시 Perl에 익숙한 -d 플래그를 공급해 호출해요.
$> 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: 1701
Devel::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](https://metacpan.org/pod/Apache::SmallProf)도 참고하세요.
Devel::FastProf
Devel::FastProf는 또 다른 Perl 줄 프로파일러예요. Devel::SmallProf보다 빠른 줄 프로파일러를 얻기 위해 작성됐는데, C로 쓰여 있기 때문이에요. Devel::FastProf를 쓰려면 Perl에 -d 인자를 공급해요:
$> 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: 1701
Devel::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::* 네임스페이스 아래 실행되는 데이터베이스 쿼리를 프로파일링하는 DBIx::Profile도 참고하세요.
Devel::NYTProf
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: 1701
NYTProf는 기본적으로 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를 mod_perl에 연결하는 [Devel::NYTProf::Apache](https://metacpan.org/pod/Devel::NYTProf::Apache)도 참고하세요.
정렬 (SORTING)
Perl 모듈이 성능 분석가가 곁에 둔 유일한 도구는 아니에요. 다음 예시에서 보여주듯 time 같은 시스템 도구도 간과해선 안 돼요. 정렬을 빠르게 살펴볼게요. 효율적인 정렬 알고리즘에 대한 책, 논문, 기사가 많이 쓰였고, 여기가 그 작업을 반복할 자리는 아니에요. 살펴볼 가치가 있는 좋은 정렬 모듈도 몇 개 있어요. Sort::Maker, Sort::Key가 떠오르네요. 하지만 데이터 셋 정렬과 관련된 문제에 대한 어떤 Perl 특유의 해석에 대해 몇 가지 관찰을 하고, 대량 데이터 정렬이 성능에 어떻게 영향을 줄 수 있는지에 대한 예를 한두 개 드는 건 여전히 가능해요. 먼저, 대량 데이터를 정렬할 때 자주 간과되는 점인데, 다룰 데이터 셋을 줄이려고 시도할 수 있어요. 많은 경우 grep()이 단순한 필터로 꽤 유용할 수 있어요:
@data = sort grep { /$filter/ } @incoming
이런 명령은 먼저 실제로 정렬할 재료의 양을 크게 줄일 수 있어요. 그 단순함만으로 너무 가볍게 무시해선 안 돼요. KISS 원칙(Keep It Simple, Stupid)이 너무 자주 간과돼요. 다음 예시는 이를 보여주기 위해 단순한 시스템 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줄을 Response Code, Query, Browser, Referring Url, 마지막으로 Date 순으로 정렬하는 거예요. 한 해법은 커맨드라인에 주어진 파일들을 반복하는 다음 코드를 쓰는 거예요.
#!/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
프로그램은 wallclock으로 17초 조금 넘게 걸려 실행됐어요. time이 출력하는 서로 다른 값을 주목하세요. 항상 같은 값을 쓰는 게 중요하고, 각각이 무엇을 뜻하는지 혼동하지 않는 게 중요해요.
경과 실시간 (Elapsed Real Time)
time이 호출됐을 때부터 종료될 때까지의 전체(또는 wallclock) 시간이에요. 경과 시간은 user와 system 시간을 모두 포함하고, 시스템의 다른 사용자와 프로세스를 기다린 시간도 포함해요. 불가피하게, 주어진 측정 중 가장 근사한 값이에요.
User CPU 시간 (User CPU Time)
user 시간은 전체 프로세스가 이 시스템에서 이 프로그램을 실행하며 사용자를 대신해 보낸 시간이에요.
System CPU 시간 (System CPU Time)
system 시간은 커널 자체가 이 프로세스 사용자를 대신해 루틴, 즉 시스템 콜을 실행하는 데 보낸 시간이에요.
이 같은 프로세스를 Schwarzian Transform으로 실행하면 모든 데이터를 저장하는 입력·출력 배열을 없애고, 도착하는 대로 입력에 직접 작업할 수 있어요. 그 외의 코드는 꽤 비슷해 보여요:
#!/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
BTW. 프로그램을 한 번 런타임의 50%나 빠르게 만들었다는 걸 본 매니저가, 한 달 뒤에 같은 걸 또 해달라는 요청을 받는 압박(실화예요)도 조심하세요. 여러분은 Perl 프로그래머라도 사람일 뿐이라고 지적하고, 할 수 있는 걸 해보겠다고 하면 돼요...
로깅 (LOGGING)
어떤 좋은 개발 과정에도 필수적인 부분은 적절히 정보를 주는 메시지로 적절한 오류 처리를 하는 거예요. 하지만 로그 파일이 수다스러워야 한다는 학파가 존재해요. 마치 끊기지 않는 출력의 사슬이 프로그램의 생존을 보장하는 것처럼요. 속도가 어떤 식으로든 문제라면, 이 접근은 틀렸어요.
흔히 보이는 코드는 이렇게 생겼어요:
logger->debug( "A logging message via process-id: $$ INC: "
. Dumper(\%INC) )
문제는 로깅 설정 파일에 설정된 디버그 레벨이 0일 때조차 이 코드가 항상 파싱되고 실행된다는 거예요. debug() 서브루틴이 입력되고 내부 $debug 변수가 0임을 확인하면, 들어온 메시지는 버려지고 프로그램은 계속될 거예요. 하지만 위 예시에서는 \%INC 해시가 이미 덤프되고 메시지 문자열이 구성됐을 거예요. 이 모든 작업은 문장 수준의 디버그 변수로 우회할 수 있어요. 이렇게요:
logger->debug( "A logging message via process-id: $$ INC: "
. Dumper(\%INC) ) if $DEBUG;
이 효과는 두 형태를 모두 포함한 테스트 스크립트를 설정해 보여줄 수 있어요. 전형적인 logger() 기능을 흉내 내는 debug() 서브루틴을 포함해서요.
#!/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초가 걸리고, 다른 경우에는 100분의 1초가 걸려요. 꽤 결정적인 것 같죠. 서브루틴 안의 똑똑한 기능에 의존하기보다, 서브루틴을 호출하기 전에 $DEBUG 변수를 사용하세요.
DEBUG일 때 로깅 (상수) (Logging if DEBUG (constant))
컴파일 타임 DEBUG 상수를 써서 이전 아이디어를 조금 더 발전시킬 수 있어요.
#!/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 변수조차 박살 내버려요. 마이너스 0초에 도달하면서, 곁들여 "너무 적은 반복이어서 신뢰할 수 없는 횟수" 경고 메시지까지 생성하죠. 무슨 일이 실제로 벌어지는지, 그리고 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 상수의 값, 즉 0으로 대체됐음을 보여줘요. 테스트될 줄이 완전히 최적화되어 사라졌어요. 그것보다 더 효율적일 수는 없죠.
후기 (POSTSCRIPT)
이 문서는 핫 스팟을 식별하고, 어떤 수정이 코드의 런타임을 개선했는지 확인하는 여러 방법을 제공했어요.
마지막 생각으로, (이 글을 쓰는 시점에) 0이나 음수 시간에 실행될 유용한 프로그램을 만드는 건 불가능하다는 걸 기억하세요. 이 기본 원칙은 이렇게 쓸 수 있어요: 유용한 프로그램은 정의상 느리다. 물론 거의 순간적인 프로그램을 쓰는 건 가능해요. 하지만 그다지 많은 일을 하지는 않을 거예요. 여기 아주 효율적인 것이 있어요:
$> perl -e 0
그것을 더 최적화하는 건 p5p의 몫이에요.
함께 보기 (SEE ALSO)
추가 자료는 아래 모듈과 링크에서 찾을 수 있어요.
PERLDOCS
예: perldoc -f sort.
perlfork, perlfunc, perlretut, perlthrtut.
MAN PAGES
time.
MODULES
여기서 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
URLS
매우 유용한 온라인 참고 자료:
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.html
저자 (AUTHOR)
Richard Foley [email protected] Copyright (c) 2008
Perldoc Browser는 Dan Book(DBOOK)이 유지보수해요. 사이트 자체, 검색, 문서 렌더링 관련 문제는 GitHub issue tracker로 연락하세요.
Perl 문서는 Perl 5 Porters가 Perl 개발 과정에서 유지보수해요. 문서 내용이나 형식 관련 문제는 Perl issue tracker, 메일링 리스트, 또는 IRC로 연락하세요.