On Mon, 2005-09-19 at 22:17 -0700, Mike Schilli wrote:
>
> Thanks for the patch, it's been applied and will be released with 1.01.
>
Great! My first patch committed to an open-source program. :)
> The patch will increase performance only during init(), you must be
> calling init() fairly often to see a difference. Since init() should
> only be called at startup, you must have an unusual use case I'd like
> to hear about.
In summary, the perf impact sticks out because of the number of custom
levels and the size of the config. It is only a one time impact (as you
say, only during init()), but if you have a sizable configuration,
generate_is_xxx_codref will eventually bubble up to the top of your
dprofpp output for things like getting a usage statement.
Gory details below...
After analysis, it turns out that adding custom levels (I know, it's
discouraged!) significantly increases the number of calls to
generate_is_xxx_coderef(). I would estimate it's about 50 calls per
level - This has to do with the complexity of my log configuration. If
I reduce the complexity, that number, 50, goes down.
Interesting as well, we start at over 200 calls to this subroutine just
when calling a plain init() (no extra custom levels, again config
complexity is the factor).
Here is the profile total before the patch:
15.2 0.059 0.059 203 0.0003 0.0003 Log::Log4perl::Logger::generate_is_xxx_coderef
Here is the profile after the patch:
0.00 - -0.001 203 - - Log::Log4perl::Logger::generate_is_xxx_coderef
Ordinarily, 5 100ths of a seconds, wouldn't bother me. Although, 15% of
the time of the small test program is a lot. But look what happens when
I put in my extra levels (I have a lot to facilitate the replacement of
both our old logging system and our old debugging system, which had this
notion of levels that couldn't be easily integrated into categories --
for new things I'm using categories).
$ dprofpp -g Log::Log4perl::Logger::generate_is_xxx_coderef
Total Elapsed Time = 0.524141 Seconds
User+System Time = 0.117070 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
99.9 0.117 0.117 651 0.0002 0.0002 Log::Log4perl::Logger::generate_is_xxx_coderef
$
That line goes to near 0 when I apply the patch.
All that was on my small test program that simply initialized. If I
look at the real world, it is between 11-20% of the initialization time
of my scripts was spent in this function, depending on the script. That
was anywhere from .1 to .3 seconds wasted during every program run,
depending on the speed of the system. Also, as the complexity of my log
config grows the number will only increase.
That improvement isn't "earth-shattering" but every little bit counts
when talking about oft used command-line programs. :)
--
David Britton
|
