# -*- perl -*-
=head1 TITLE
Using optimizer to do Method Munging. (as done in
Log::Log4perl::AutoCategorize)
=head1 Munging (from C++)
A Term borrowed from C++; it disambiguates same-named functions in
different classes, or with different argument or return types.
It allowed a C++ front-end to use a C compiler back-end.
Example:
public class A {
int foo();
int foo(int);
}
public class B : public A {
String foo();
String foo(String);
}
yielding something like: (its internal to compile/link so doesnt matter)
foo_A_void;
foo_A_int;
foo_B_void;
foo_B_String;
The reasons we do it are different, but the operation is similar; it
'alters' the symbol table.
=head1 Reason to Munge
At compile time, we want to convert all instances of:
FROM: {
Logger->debug ("msg A");
Logger->debug ("msg B");
}
TO: {
Logger->debug_001 ("msg A");
Logger->debug_002 ("msg B");
}
Each invocation gets its own B<UNIQUE> function-name (an arbitrary one)
=head2 Why?
So we can create custom handlers for each.. (hold this thought)
=head1 Motivating Application: logging with Log::Log4perl
Log::Log4perl provides a powerful, flexible way to redirect and filter
logging via config-file, and the 'category' that the programmer writes
into his classes.
Its problem is that using the power requires that the programmer be
careful and diligent with his categorization used in his logging.
=head2 Log::Log4perl powerful example
# load a config-string (or file)
Log::Log4perl->init(\ qq{
log4perl.category.Candy.Twix = DEBUG, Screen
log4perl.category.Candy.Snickers = INFO, Screen
});
# now use that logger
package Candy::Twix;
sub new {
my $logger = Log::Log4perl->new("Candy::Twix::new");
$logger->debug("Creating a new Twix bar");
bless {}, shift;
}
=head2 Notes about above example
new() has its own category, implying that each method would also have
its own. This represents a coding burden on the client. The category
must be manually added to each method, even though its known to perl,
via caller().
You're wise to keep category consistent with (ie the same as) the
package and method.
The config-string has a logging category for Bar::Twix only, not for
each of its methods. This example doesnt do detailed control of
logging, but its possible later (assuming a config-file) because
methods use distinct categories.
=head2 Log::Log4perl qw(:easy);
In easy mode, Log4perl sets $category = __PACKAGE__
No work for the programmer, but gives a lot less control over what
gets logged.
Sorry Virginia, there is no __SUBROUTINE__.
=head1 You can have both ease and power, with Log::Log4perl::AutoCategorize
AutoCategorize is a wrapper on Log::Log4perl, and uses its log-config
and filtering mechanisms. However, it extends the $category, giving
the filters more detailed info to act upon..
In Log4perl ':easy':
$category = "$package";
In Log::Log4perl::AutoCategorize:
$category = "$package.$subroutine.$loggingLevel.$lineNumber";
Now filtering, as specified in your log-config, can tease out every
invocation individually.
=head1 OK, wheres optimizer come into it ?
In Log4perl, every time $logger->debug() is called, it must decide:
I<what to do with the message?>
I made it worse; now $category includes info that only caller() can
provide. This adds significant runtime cost (esp for an
application-wide logger).
I<However>.. by differentiating each caller B<with a unique method
name>, the name can be associated with the log / dont-log choice, and
'remembered' by a custom subroutine, which is added to the symbol
table.
The next time that munged method (ex: debug_00001) is called,
AutoCategorize::AUTOLOAD is uninvolved; the recently vivified method
is dispatched directly.
This actually executes faster than Log4perl, and up-front munging cost
is quickly amortized, though at cost of more memory for code.
=head2 Youre still using caller() at runtime. Why ?
To compute the $category, caller() must be looking at the real
call-stack. At compile-time, the only thing on the stack (besides the
optimizer callback) is an __ANON__ block.
Since we cant determine a category at runtime, the munge is arbitrary,
and _00001++ is as good as any.
=head1 Shameless plug
Since Log::Log4perl::AutoCategorize knows all logging calls, and knows
which ones were actually invoked, it gives you a detailed coverage
report for free.
[jimc@harpo t]$ mroe out.cover.tconf_file
(19:44:06.204) Log.Log4perl.AutoCategorize.END.info.308: Seen Log Events:, {
'Log.Log4perl.AutoCategorize.END.info.308' => 1,
'log4perl.category.A.truck.debug.63' => 20,
'log4perl.category.A.truck.debug.65' => 20,
'log4perl.category.A.truck.debug.66' => 20,
'log4perl.category.A.truck.warn.62' => 20,
'log4perl.category.main.car.warn.46' => 10,
'log4perl.category.main.main.info.28' => 5,
'log4perl.category.main.main.warn.27' => 5,
'log4perl.category.main.suv.warn.51' => '-10',
'log4perl.category.main.suv.warn.52' => '-10'
}
(19:44:06.207) Log.Log4perl.AutoCategorize.END.info.308: un-Seen Log Events:, {
'info_00011' => 'main,tconf_file.pl,36',
'warn_00008' => 'B::C,tconf_file.pl,76'
}
(19:44:06.210) Log.Log4perl.AutoCategorize.END.info.308: cat2data:, {
'A.truck.debug.63' => 'debug_00005',
'A.truck.debug.65' => 'debug_00006',
'A.truck.debug.66' => 'debug_1_00007',
'A.truck.warn.62' => 'warn_00004',
'main.car.warn.46' => 'warn_00001',
'main.main.info.28' => 'info_00010',
'main.main.warn.27' => 'warn_00009',
'main.suv.warn.51' => 'warn_00002',
'main.suv.warn.52' => 'warn_00003'
}
As a convenience, it also dumps ref-data args.
=head2 Notes on Coverage Report
%Seen counts number of times the call was made, positive numbers mean
the logging was enabled, negative means suppressed.
%UnSeen calls were never reached, and may represent testing
inadequacies.
I eat my own dog-food; the same logging mechanisms issue a report from
an END block, and are re-directable using any Log4perl means.
=head1 Conclusions
optimizer is BADDASS, this is a fairly trivial usage.
I had a couple surprises, particularly with B::NULL ops. These are
probably remnants of optimization done before I get called.
My optimzer callback recognizes and alters this opcode chain:
perl -MO=Concise,-exec -e 'Logger->debug([{1=>"a"}])'
Arthur Bergman is talking tomorrow on optimizer.pm
All flavors of munging require AUTOLOAD to handle the munged
functions. Otherwize, you'd not bother munging, and just code it
directly.
This is only useful in a situation where you need info about your
caller; ie where you have to make a decision that needs it as input.
Munging worked here because:
=item
we're too lazy to provide our own categories
=item
the caller-info was an acceptable approximation of what
we would do if we werent so lazy
=item
laziness is a virtue :-)