I just debugged a wild situation in DBM::Deep's test suite and thought I'd share.

DBM::Deep will handle either hashes or arrays in a hybrid tied/OO interface. To make sure that we're always working with the tied object (which is a blessed hashref) as opposed to the blessed reference to the tied array/hash, we have the following gatekeeper methods:

package DBM::Deep::Array;

sub _get_self {
    eval { tied( @{$_[0]} ) } || $_[0]
}

package DBM::Deep::Hash;

sub _get_self {
    eval { tied( %{$_[0]} ) } || $_[0]
}
[download]

Several of our tests are stress tests, meant to verify that certain things occur which only occur after thousands of keys are used. They are bighash.t and bigarray.t, and the code is identical except for the type (one is TYPE_HASH and the other is TYPE_ARRAY). Because of the internals, we expected bigarray to run about 3x slower than bighash.

Here's where it gets interesting - bigarray was running 10x slower than bighash. We did some basic print-statement profiling, but nothing was jumping out at us. So, we pulled out Devel::DProf. The profile for bighash was as expected. The profile for bigarray, however, had something completely unexpected. Well over 70% of the time was being taken by Test::Builder::__ANON__.

%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 99.6   61.24 61.244 602629   0.0001 0.0001  Test::Builder::__ANON__
 19.1   11.79 73.033 610623   0.0000 0.0001  DBM::Deep::Array::_get_se
+lf
 2.62   1.610 11.770  33693   0.0000 0.0003  DBM::Deep::_load_tag
 1.79   1.103  8.684   8002   0.0001 0.0011  DBM::Deep::_add_bucket
 1.48   0.910 40.633 318635   0.0000 0.0001  DBM::Deep::root
[download]

The key here is not the Test::Builder::__ANON__ line by itself, but it combined with the _get_self line, particularly the ExclSec vs. CumlSec. Notice how the difference between CumlSec and ExclSec in the _get_self line is almost exactly the amount of time taken by the Test::Builder::__ANON__ line. But, we didn't quite see it yet.

Since we couldn't find out which subroutine in Test::Builder was being called, we turned to Sub::Name, which allows you to name an anonymous sub. We went ahead and named every place we saw "sub {...}" in Test::Builder with foo1, foo2, etc. And, it immediately became obvious. It was the $SIG{__DIE__} handler in Test::Builder. Reading eval, about halfway down, we found the following tidbit:

Using the eval{} form as an exception trap in libraries does have some issues. Due to the current arguably broken state of __DIE__ hooks, you may wish not to trigger any __DIE__ hooks that user code may have installed. You can use the local $SIG{__DIE__} construct for this purpose, as shown in this example:

In our case, we were caught by a __DIE__ hook in a library.

---

---

Posts are HTML formatted. Put <p> </p> tags around your paragraphs. Put <code> </code> tags around your code and data!

Titles consisting of a single word are discouraged, and in most cases are disallowed outright.

Read Where should I post X? if you're not absolutely sure you're posting in the right place.

Please read these before you post! —

• How do I compose an effective node title?
• How do I post a question effectively?
• Markup in the Monastery

Posts may use any of the Perl Monks Approved HTML tags:

a, abbr, b, big, blockquote, br, caption, center, col, colgroup, dd, del, details, div, dl, dt, em, font, h1, h2, h3, h4, h5, h6, hr, i, ins, li, ol, p, pre, readmore, small, span, spoiler, strike, strong, sub, summary, sup, table, tbody, td, tfoot, th, thead, tr, tt, u, ul, wbr

You may need to use entities for some characters, as follows. (Exception: Within code tags, you can put the characters literally.)

	For:		Use:
	&		&
	<		&lt;
	>		&gt;
	[		&#91;
	]		&#93;

Link using PerlMonks shortcuts! What shortcuts can I use for linking?

See Writeup Formatting Tips and other pages linked from there for more info.