← Index
NYTProf Performance Profile   « line view »
For nd2: #2 manager: init
  Run on Thu May 2 17:38:58 2019
Reported on Thu May 2 17:40:49 2019

Filename/appl/netdisco/perl5/lib/perl5/Dancer/Logger/Abstract.pm
StatementsExecuted 1485 statements in 6.33ms
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
33113.52ms7.50msDancer::Logger::Abstract::::format_messageDancer::Logger::Abstract::format_message
13211458µs1.78msDancer::Logger::Abstract::::__ANON__[:125]Dancer::Logger::Abstract::__ANON__[:125]
3311299µs9.66msDancer::Logger::Abstract::::debugDancer::Logger::Abstract::debug
3311259µs671µsDancer::Logger::Abstract::::_shouldDancer::Logger::Abstract::_should
3311220µs1.18msDancer::Logger::Abstract::::__ANON__[:101]Dancer::Logger::Abstract::__ANON__[:101]
16511185µs185µsDancer::Logger::Abstract::::CORE:substcontDancer::Logger::Abstract::CORE:substcont (opcode)
3311164µs297µsDancer::Logger::Abstract::::_log_formatDancer::Logger::Abstract::_log_format
3311155µs155µsDancer::Logger::Abstract::::CORE:substDancer::Logger::Abstract::CORE:subst (opcode)
331163µs63µsDancer::Logger::Abstract::::__ANON__[:102]Dancer::Logger::Abstract::__ANON__[:102]
331144µs44µsDancer::Logger::Abstract::::__ANON__[:108]Dancer::Logger::Abstract::__ANON__[:108]
331130µs30µsDancer::Logger::Abstract::::__ANON__[:103]Dancer::Logger::Abstract::__ANON__[:103]
0000s0sDancer::Logger::Abstract::::BEGINDancer::Logger::Abstract::BEGIN
0000s0sDancer::Logger::Abstract::::__ANON__[:100]Dancer::Logger::Abstract::__ANON__[:100]
0000s0sDancer::Logger::Abstract::::__ANON__[:107]Dancer::Logger::Abstract::__ANON__[:107]
0000s0sDancer::Logger::Abstract::::__ANON__[:109]Dancer::Logger::Abstract::__ANON__[:109]
0000s0sDancer::Logger::Abstract::::__ANON__[:110]Dancer::Logger::Abstract::__ANON__[:110]
0000s0sDancer::Logger::Abstract::::__ANON__[:113]Dancer::Logger::Abstract::__ANON__[:113]
0000s0sDancer::Logger::Abstract::::__ANON__[:88]Dancer::Logger::Abstract::__ANON__[:88]
0000s0sDancer::Logger::Abstract::::__ANON__[:95]Dancer::Logger::Abstract::__ANON__[:95]
0000s0sDancer::Logger::Abstract::::__ANON__[:97]Dancer::Logger::Abstract::__ANON__[:97]
0000s0sDancer::Logger::Abstract::::__ANON__[:98]Dancer::Logger::Abstract::__ANON__[:98]
0000s0sDancer::Logger::Abstract::::_logDancer::Logger::Abstract::_log
0000s0sDancer::Logger::Abstract::::coreDancer::Logger::Abstract::core
0000s0sDancer::Logger::Abstract::::errorDancer::Logger::Abstract::error
0000s0sDancer::Logger::Abstract::::infoDancer::Logger::Abstract::info
0000s0sDancer::Logger::Abstract::::warningDancer::Logger::Abstract::warning
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments		 Time
on line		 Calls Time
in subs		 Code
1package Dancer::Logger::Abstract;
2our $AUTHORITY = 'cpan:SUKRIA';
3#ABSTRACT: Abstract logging engine for Dancer
4$Dancer::Logger::Abstract::VERSION = '1.3512';
5use strict;
6use warnings;
7use Carp;
8use base 'Dancer::Engine';
9
10use Dancer::SharedData;
11use Dancer::Timer;
12use Dancer::Config 'setting';
13use POSIX qw/strftime/;
14
15# This is the only method to implement by logger engines.
16# It receives the following arguments:
17# $msg_level, $msg_content, it gets called only if the configuration allows
18# a message of the given level to be logged.
19sub _log { confess "_log not implemented" }
20
21my $levels = {
22
23 # levels < 0 are for core only
24 core => -10,
25
26 # levels > 0 are for end-users only
27 debug => 1,
28 info => 2,
29 warn => 3,
30 warning => 3,
31 error => 4,
32};
33
34my $log_formats = {
35 simple => '[%P] %L @%D> %i%m in %f l. %l',
36};
37
38
# spent 297µs (164+132) within Dancer::Logger::Abstract::_log_format which was called 33 times, avg 9µs/call: # 33 times (164µs+132µs) by Dancer::Logger::Abstract::format_message at line 127, avg 9µs/call
sub _log_format {
393338µs33132µs my $config = setting('logger_format');
# spent 132µs making 33 calls to Dancer::Config::setting, avg 4µs/call
40
413312µs if ( !$config ) {
42 return $log_formats->{simple};
43 }
44
453369µs exists $log_formats->{$config}
46 ? return $log_formats->{$config}
47 : return $config;
48}
49
50
# spent 671µs (259+411) within Dancer::Logger::Abstract::_should which was called 33 times, avg 20µs/call: # 33 times (259µs+411µs) by Dancer::Logger::Abstract::debug at line 140, avg 20µs/call
sub _should {
513330µs my ($self, $msg_level) = @_;
5233142µs33411µs my $conf_level = setting('log') || 'debug';
# spent 411µs making 33 calls to Dancer::Config::setting, avg 12µs/call
53
543341µs if (!exists $levels->{$conf_level}) {
55 setting('log' => 'debug');
56 $conf_level = 'debug';
57 }
58
593379µs return $levels->{$conf_level} <= $levels->{$msg_level};
60}
61
62
# spent 7.50ms (3.52+3.99) within Dancer::Logger::Abstract::format_message which was called 33 times, avg 227µs/call: # 33 times (3.52ms+3.99ms) by Dancer::Logger::Console::_log at line 11 of Dancer/Logger/Console.pm, avg 227µs/call
sub format_message {
633328µs my ($self, $level, $message) = @_;
643343µs chomp $message;
65
6633157µs991.51ms $message = Encode::encode(setting('charset'), $message)
# spent 1.33ms making 33 calls to Encode::encode, avg 40µs/call # spent 172µs making 66 calls to Dancer::Config::setting, avg 3µs/call
67 if setting('charset');
68
693322µs $level = 'warn' if $level eq 'warning';
703353µs $level = sprintf('%5s', $level);
71
7233142µs3367µs my $r = Dancer::SharedData->request;
# spent 67µs making 33 calls to Dancer::SharedData::request, avg 2µs/call
7333243µs my @stack = caller(3);
74
75 my $block_handler = sub {
76 my ( $block, $type ) = @_;
77 if ( $type eq 't' ) {
78 return "[" . strftime( $block, localtime ) . "]";
79 }
80 elsif ( $type eq 'h' ) {
81 return '-' unless defined $r;
82 return scalar $r->header($block) || '-';
83 }
84 else {
85 Carp::carp("{$block}$type not supported");
86 return "-";
87 }
8833239µs };
89
90 my $chars_mapping = {
91 h => sub {
92 defined $r
93 ? $r->env->{'HTTP_X_REAL_IP'} || $r->env->{'REMOTE_ADDR'} || '-'
94 : '-';
95 },
96 t => sub { Encode::decode(setting('charset') || 'utf8',
97 POSIX::strftime( "%d/%b/%Y %H:%M:%S", localtime )) },
98 T => sub { POSIX::strftime( "%Y-%m-%d %H:%M:%S", localtime ) },
99 u => sub { Encode::decode(setting('charset') || 'utf8',
100 POSIX::strftime( "%d/%b/%Y %H:%M:%S", gmtime )) },
101331.22ms33960µs
# spent 1.18ms (220µs+960µs) within Dancer::Logger::Abstract::__ANON__[/appl/netdisco/perl5/lib/perl5/Dancer/Logger/Abstract.pm:101] which was called 33 times, avg 36µs/call: # 33 times (220µs+960µs) by Dancer::Logger::Abstract::__ANON__[/appl/netdisco/perl5/lib/perl5/Dancer/Logger/Abstract.pm:125] at line 124, avg 36µs/call
U => sub { POSIX::strftime( "%Y-%m-%d %H:%M:%S", gmtime ) },
# spent 960µs making 33 calls to POSIX::strftime, avg 29µs/call
10233117µs
# spent 63µs within Dancer::Logger::Abstract::__ANON__[/appl/netdisco/perl5/lib/perl5/Dancer/Logger/Abstract.pm:102] which was called 33 times, avg 2µs/call: # 33 times (63µs+0s) by Dancer::Logger::Abstract::__ANON__[/appl/netdisco/perl5/lib/perl5/Dancer/Logger/Abstract.pm:125] at line 124, avg 2µs/call
P => sub { $$ },
1033363µs
# spent 30µs within Dancer::Logger::Abstract::__ANON__[/appl/netdisco/perl5/lib/perl5/Dancer/Logger/Abstract.pm:103] which was called 33 times, avg 906ns/call: # 33 times (30µs+0s) by Dancer::Logger::Abstract::__ANON__[/appl/netdisco/perl5/lib/perl5/Dancer/Logger/Abstract.pm:125] at line 124, avg 906ns/call
L => sub { $level },
104 D => sub {
105 my $time = Dancer::SharedData->timer->tick;
106 return $time;
107 },
1083377µs
# spent 44µs within Dancer::Logger::Abstract::__ANON__[/appl/netdisco/perl5/lib/perl5/Dancer/Logger/Abstract.pm:108] which was called 33 times, avg 1µs/call: # 33 times (44µs+0s) by Dancer::Logger::Abstract::__ANON__[/appl/netdisco/perl5/lib/perl5/Dancer/Logger/Abstract.pm:125] at line 124, avg 1µs/call
m => sub { $message },
109 f => sub { $stack[1] || '-' },
110 l => sub { $stack[2] || '-' },
111 i => sub {
112 defined $r ? "[hit #" . $r->id . "]" : "";
113 },
114331.12ms };
115
116
# spent 1.78ms (458µs+1.32) within Dancer::Logger::Abstract::__ANON__[/appl/netdisco/perl5/lib/perl5/Dancer/Logger/Abstract.pm:125] which was called 132 times, avg 13µs/call: # 132 times (458µs+1.32ms) by Dancer::Logger::Abstract::format_message at line 129, avg 13µs/call
my $char_mapping = sub {
11713247µs my $char = shift;
118
11913244µs my $cb = $chars_mapping->{$char};
12013215µs unless ($cb) {
121 Carp::carp "\%$char not supported.";
122 return "-";
123 }
124132284µs1321.32ms $cb->($char);
# spent 1.18ms making 33 calls to Dancer::Logger::Abstract::__ANON__[Dancer/Logger/Abstract.pm:101], avg 36µs/call # spent 63µs making 33 calls to Dancer::Logger::Abstract::__ANON__[Dancer/Logger/Abstract.pm:102], avg 2µs/call # spent 44µs making 33 calls to Dancer::Logger::Abstract::__ANON__[Dancer/Logger/Abstract.pm:108], avg 1µs/call # spent 30µs making 33 calls to Dancer::Logger::Abstract::__ANON__[Dancer/Logger/Abstract.pm:103], avg 906ns/call
1253388µs };
126
12733114µs33297µs my $fmt = $self->_log_format();
# spent 297µs making 33 calls to Dancer::Logger::Abstract::_log_format, avg 9µs/call
128
129165770µs3302.12ms $fmt =~ s^
# spent 1.78ms making 132 calls to Dancer::Logger::Abstract::__ANON__[Dancer/Logger/Abstract.pm:125], avg 13µs/call # spent 185µs making 165 calls to Dancer::Logger::Abstract::CORE:substcont, avg 1µs/call # spent 155µs making 33 calls to Dancer::Logger::Abstract::CORE:subst, avg 5µs/call
130 (?:
131 \%\{(.+?)\}([a-z])|
132 \%([a-zA-Z])
133 )
134 ^ $1 ? $block_handler->($1, $2) : $char_mapping->($3) ^egx;
135
13633735µs return $fmt."\n";
137}
138
139sub core { $_[0]->_should('core') and $_[0]->_log('core', $_[1]) }
14033300µs669.36ms
# spent 9.66ms (299µs+9.36) within Dancer::Logger::Abstract::debug which was called 33 times, avg 293µs/call: # 33 times (299µs+9.36ms) by Dancer::Logger::debug at line 37 of Dancer/Logger.pm, avg 293µs/call
sub debug { $_[0]->_should('debug') and $_[0]->_log('debug', $_[1]) }
# spent 8.69ms making 33 calls to Dancer::Logger::Console::_log, avg 263µs/call # spent 671µs making 33 calls to Dancer::Logger::Abstract::_should, avg 20µs/call
141sub info { $_[0]->_should('info') and $_[0]->_log('info', $_[1]) }
142sub warning { $_[0]->_should('warning') and $_[0]->_log('warning', $_[1]) }
143sub error { $_[0]->_should('error') and $_[0]->_log('error', $_[1]) }
144
1451;
146
147__END__
 
# spent 155µs within Dancer::Logger::Abstract::CORE:subst which was called 33 times, avg 5µs/call: # 33 times (155µs+0s) by Dancer::Logger::Abstract::format_message at line 129, avg 5µs/call
sub Dancer::Logger::Abstract::CORE:subst; # opcode
# spent 185µs within Dancer::Logger::Abstract::CORE:substcont which was called 165 times, avg 1µs/call: # 165 times (185µs+0s) by Dancer::Logger::Abstract::format_message at line 129, avg 1µs/call
sub Dancer::Logger::Abstract::CORE:substcont; # opcode
Report produced by the NYTProf 6.06 Perl profiler, developed by Tim Bunce based on work by Adam Kaplan and Salvador Fandiño García.