Why is Perl's Math::Complex taking up so much time when I try acos(1)?

Question

While trying to profile my Perl program, I find that Math::Complex is taking up a lot of time with what looks like some kind of warning.

Also, my code shouldn't have any complex numbers being generated or used, so I am not sure what it is doing in Math::Complex, anyway. Here's the FastProf output for the most expensive lines:

/usr/lib/perl5/5.8.8/Math/Complex.pm:182 1.55480 276232: _cannot_make("real part",      $re) unless $re =~ /^$gre$/;
/usr/lib/perl5/5.8.8/Math/Complex.pm:310 1.01132 453641: sub cartesian {$_[0]->{c_dirty} ?
/usr/lib/perl5/5.8.8/Math/Complex.pm:315 0.97497 562188: sub set_cartesian { $_[0]->{p_dirty}++; $_[0]->{c_dirty} = 0;
/usr/lib/perl5/5.8.8/Math/Complex.pm:189 0.86302 276232: return $self;
/usr/lib/perl5/5.8.8/Math/Complex.pm:1332 0.85628 293660: $self->{display_format} = { %display_format };
/usr/lib/perl5/5.8.8/Math/Complex.pm:185 0.81529 276232: _cannot_make("imaginary part", $im) unless $im =~ /^$gre$/;
/usr/lib/perl5/5.8.8/Math/Complex.pm:1316 0.78749 293660: my %display_format = %DISPLAY_FORMAT;
/usr/lib/perl5/5.8.8/Math/Complex.pm:1335 0.69534 293660: %{$self->{display_format}} :
/usr/lib/perl5/5.8.8/Math/Complex.pm:186 0.66697 276232: $self->set_cartesian([$re, $im ]);
/usr/lib/perl5/5.8.8/Math/Complex.pm:170 0.62790 276232: my $self = bless {}, shift;
/usr/lib/perl5/5.8.8/Math/Complex.pm:172 0.56733 276232: if (@_ == 0) {
/usr/lib/perl5/5.8.8/Math/Complex.pm:316 0.53179 281094: $_[0]->{'cartesian'} = $_[1] }
/usr/lib/perl5/5.8.8/Math/Complex.pm:1324 0.48768 293660: if (@_ == 1) {
/usr/lib/perl5/5.8.8/Math/Complex.pm:1319 0.44835 293660: if (exists $self->{display_format}) {
/usr/lib/perl5/5.8.8/Math/Complex.pm:1318 0.40355 293660: if (ref $self) {   # Called as an object method
/usr/lib/perl5/5.8.8/Math/Complex.pm:187 0.39950 276232: $self->display_format('cartesian');
/usr/lib/perl5/5.8.8/Math/Complex.pm:1315 0.39312 293660: my $self  = shift;
/usr/lib/perl5/5.8.8/Math/Complex.pm:1331 0.38087 293660: if (ref $self) { # Called as an object method
/usr/lib/perl5/5.8.8/Math/Complex.pm:184 0.35171 276232: $im ||= 0;
/usr/lib/perl5/5.8.8/Math/Complex.pm:181 0.34145 276232: if (defined $re) {
/usr/lib/perl5/5.8.8/Math/Complex.pm:171 0.33492 276232: my ($re, $im);
/usr/lib/perl5/5.8.8/Math/Complex.pm:390 0.20658 128280: my ($z1, $z2, $regular) = @_;
/usr/lib/perl5/5.8.8/Math/Complex.pm:391 0.20631 128280: if ($z1->{p_dirty} == 0 and ref $z2 and $z2->{p_dirty} == 0) {

Thanks for any help!

Answer 1

Lines 182 and 185 do a warning unless a regex matches. So the slowness is probably not from outputting warnings but rather doing the regular expression matching.

If the profiler says those lines are being executed, they are. If you aren't calling them directly, a module that you load may be calling them indirectly. If you use a more advanced profiler (such as Devel::NYTProf), you'll be able to see the call graph to determine what part of your code is ultimately causing the call to the slow library code.

Answer 2

Edit Math/Complex.pm and put

use Carp;
Carp::cluck("in Math/Complex.pm");

around one of the lines listed above. This will print out a stack trace and you will see exactly how you are getting into this module.

Answer 3

According to the perl debugger doc, you can set up a handler for the INT signal. Then while it's running you can type Ctrl-C, and it will enter the debugger. Then type T to get a backtrace, and it should show you exactly why it is in the Complex.pm code. Since you are spending a lot of time in that code, you will probably land in it, but if you don't, try it again until you do.