Author: spadkins
Date: Tue Aug 26 14:19:03 2008
New Revision: 11676
Modified:
p5ee/trunk/App-Context/lib/App/Context.pm
p5ee/trunk/App-Context/lib/App/Context/POE/ClusterController.pm
p5ee/trunk/App-Context/lib/App/Context/POE/ClusterNode.pm
p5ee/trunk/App-Context/lib/App/Context/POE/Server.pm
Log:
add profiling
Modified: p5ee/trunk/App-Context/lib/App/Context.pm
==============================================================================
--- p5ee/trunk/App-Context/lib/App/Context.pm (original)
+++ p5ee/trunk/App-Context/lib/App/Context.pm Tue Aug 26 14:19:03 2008
@@ -1688,6 +1688,86 @@
&App::sub_exit() if ($App::trace);
}
+sub profile_start {
+ my ($self, $key) = @_;
+ my $profile_state = $self->{profile_state};
+ if (!$profile_state) {
+ $profile_state = {
+ last_timeofday => [ Time::HiRes::gettimeofday() ],
+ key_stack => [],
+ };
+ $self->{profile_state} = $profile_state;
+ }
+ my $profile_stats = $self->{profile_stats};
+ if (!$profile_stats) {
+ $profile_stats = {};
+ $self->{profile_stats} = $profile_stats;
+ }
+ my $last_timeofday = $profile_state->{last_timeofday};
+ my $key_stack = $profile_state->{key_stack};
+ my $last_key = ($#$key_stack > -1) ? $key_stack->[$#$key_stack] : "";
+ my @timeofday = Time::HiRes::gettimeofday();
+ if ($last_key) {
+ my $time_elapsed = Time::HiRes::tv_interval($last_timeofday, [EMAIL
PROTECTED]);
+ $self->_profile_accumulate($profile_stats, $last_key, $time_elapsed);
+ }
+ if ($#$key_stack > 100) {
+ @$key_stack = ( $key );
+ }
+ else {
+ push(@$key_stack, $key);
+ }
+ $profile_state->{last_timeofday} = [EMAIL PROTECTED];
+}
+
+sub profile_stop {
+ my ($self, $key) = @_;
+ my $profile_state = $self->{profile_state};
+ my $profile_stats = $self->{profile_stats};
+ if ($profile_state && $profile_stats) {
+ my $last_timeofday = $profile_state->{last_timeofday};
+ my $key_stack = $profile_state->{key_stack};
+ my @timeofday = Time::HiRes::gettimeofday();
+ my $time_elapsed = Time::HiRes::tv_interval($last_timeofday, [EMAIL
PROTECTED]);
+ $self->_profile_accumulate($profile_stats, $key, $time_elapsed);
+ while ($#$key_stack > -1) {
+ my $last_key = pop(@$key_stack);
+ last if ($last_key eq $key);
+ }
+ }
+}
+
+sub _profile_accumulate {
+ my ($self, $profile_stats, $key, $time_elapsed) = @_;
+ my $stats = $profile_stats->{$key};
+ if (!defined $stats) {
+ $stats = {
+ count => 1,
+ cumul_time => $time_elapsed,
+ min_time => $time_elapsed,
+ max_time => $time_elapsed,
+ };
+ $profile_stats->{$key} = $stats;
+ }
+ else {
+ $stats->{count}++;
+ $stats->{cumul_time} += $time_elapsed;
+ $stats->{min_time} = $time_elapsed if ($time_elapsed <
$stats->{min_time});
+ $stats->{max_time} = $time_elapsed if ($time_elapsed >
$stats->{max_time});
+ }
+}
+
+sub profile_stats {
+ my ($self) = @_;
+ return($self->{profile_stats} || {});
+}
+
+sub profile_clear {
+ my ($self) = @_;
+ delete $self->{profile_stats};
+ delete $self->{profile_state};
+}
+
#############################################################################
# user()
#############################################################################
Modified: p5ee/trunk/App-Context/lib/App/Context/POE/ClusterController.pm
==============================================================================
--- p5ee/trunk/App-Context/lib/App/Context/POE/ClusterController.pm
(original)
+++ p5ee/trunk/App-Context/lib/App/Context/POE/ClusterController.pm Tue Aug
26 14:19:03 2008
@@ -210,11 +210,14 @@
my ($self, $kernel, $args) = @_[OBJECT, KERNEL, ARG0];
my ($node, $sys_info) = @$args;
- $self->log({level=>3},"poe_receive_node_status ($node) - " .
+ $self->profile_start("poe_receive_node_status") if $self->{poe_profile};
+ $self->log({level=>3},"poe_receive_node_status: BEGIN $node - " .
"load=$sys_info->{system_load}, " .
"memfree=$sys_info->{memfree}/$sys_info->{memtotal} " .
"swapfree=$sys_info->{swapfree}/$sys_info->{swaptotal}\n") if
$self->{options}{poe_trace};
$self->set_node_up($node, $sys_info);
+ $self->log({level=>3},"poe_receive_node_status: END $node\n") if
$self->{options}{poe_trace};
+ $self->profile_stop("poe_receive_node_status") if $self->{poe_profile};
&App::sub_exit() if ($App::trace);
}
@@ -228,13 +231,16 @@
my $args_str = join(",", @$args);
if ($event->{name}) {
my $service_type = $event->{service_type} || "SessionObject";
- $event_str =
"$service_type($event->{name}).$event->{method}($args_str)";
+ $event_str = "$service_type($event->{name}).$event->{method}";
}
else {
- $event_str = "$event->{method}($args_str)";
+ $event_str = "$event->{method}";
}
+ $self->profile_start("poe_run_event: $event_str") if $self->{poe_profile};
+ $self->log({level=>3},"poe_run_event: BEGIN $event_str\n") if
$self->{poe_trace};
$self->send_event($event);
-
+ $self->log({level=>3},"poe_run_event: END $event_str\n") if
$self->{poe_trace};
+ $self->profile_stop("poe_run_event: $event_str") if $self->{poe_profile};
&App::sub_exit() if ($App::trace);
}
Modified: p5ee/trunk/App-Context/lib/App/Context/POE/ClusterNode.pm
==============================================================================
--- p5ee/trunk/App-Context/lib/App/Context/POE/ClusterNode.pm (original)
+++ p5ee/trunk/App-Context/lib/App/Context/POE/ClusterNode.pm Tue Aug 26
14:19:03 2008
@@ -245,13 +245,15 @@
sub poe_cancel_async_event {
&App::sub_entry if ($App::trace);
my ( $self, $kernel, $heap, $arg0 ) = @_[ OBJECT, KERNEL, HEAP, ARG0 ];
+ $self->profile_start("poe_cancel_async_event") if $self->{poe_profile};
my ($runtime_event_token) = @$arg0;
+ $self->log({level=>3},"poe_cancel_async_event BEGIN
runtime_event_token=[$runtime_event_token]\n");
### Find if running
+ my ($event_token);
for my $pid (keys %{$self->{running_async_event}}) {
- my $event_token = $self->{running_async_event}{$pid}[0]{event_token};
+ $event_token = $self->{running_async_event}{$pid}[0]{event_token};
if ($runtime_event_token eq $event_token) {
- $self->log({level=>3},"CN : poe_cancel_async_event:
running_async_event: found event_token=[$event_token] pid=[$pid]\n");
### Kill it
if ($pid =~ /^[0-9]+$/) {
@@ -260,6 +262,7 @@
### Remove from pending
delete $self->{running_async_event}{$pid};
+ $self->log({level=>3},"poe_cancel_async_event FOUND RUNNING
event_token=[$event_token] pid=[$pid]\n");
last;
}
@@ -267,11 +270,14 @@
### Find if pending
for (my $i = 0; $i < @{$self->{pending_async_events}}; $i++) {
- my $event_token = $self->{pending_async_events}[$i][0]{event_token};
+ $event_token = $self->{pending_async_events}[$i][0]{event_token};
if ($runtime_event_token eq $event_token) {
splice(@{$self->{pending_async_events}}, $i, 1);
+ $self->log({level=>3},"poe_cancel_async_event FOUND PENDING
event_token=[$event_token]\n");
}
}
+ $self->log({level=>3},"poe_cancel_async_event END
event_token=[$event_token]\n");
+ $self->profile_stop("poe_cancel_async_event") if $self->{poe_profile};
&App::sub_exit() if ($App::trace);
}
Modified: p5ee/trunk/App-Context/lib/App/Context/POE/Server.pm
==============================================================================
--- p5ee/trunk/App-Context/lib/App/Context/POE/Server.pm (original)
+++ p5ee/trunk/App-Context/lib/App/Context/POE/Server.pm Tue Aug 26
14:19:03 2008
@@ -51,20 +51,23 @@
$self->{poe_session_name} = "poe_session";
$self->{poe_kernel} = $poe_kernel;
- $self->{num_procs} = 0;
- $self->{max_procs} = $self->{options}{"app.context.max_procs"} || 10;
- $self->{max_async_events} =
$self->{options}{"app.context.max_async_events"}
+ $self->{num_procs} = 0;
+ $self->{max_procs} =
$self->{options}{"app.context.max_procs"} || 10;
+ $self->{max_async_events} =
$self->{options}{"app.context.max_async_events"}
if (defined $self->{options}{"app.context.max_async_events"});
- $self->{max_async_events} ||= 10;
- $self->{num_async_events} = 0;
- $self->{async_event_count} = 0;
- $self->{pending_async_events} = [];
- $self->{running_async_event} = {};
+ $self->{max_async_events} ||= 10;
+ $self->{num_async_events} = 0;
+ $self->{async_event_count} = 0;
+ $self->{pending_async_events} = [];
+ $self->{running_async_event} = {};
+ $self->{poe_profile} = $options->{poe_profile};
+ $self->{poe_profile} = 60 if ($self->{poe_profile} &&
$self->{poe_profile} == 1);
+ $self->{poe_trace} = $options->{poe_trace};
$self->{verbose} = $options->{verbose};
$self->{poe_states} = [qw(
- _start _stop _default poe_sigchld poe_sigterm poe_sigignore
poe_shutdown poe_alarm
+ _start _stop _default poe_sigchld poe_sigterm poe_sigignore
poe_shutdown poe_alarm poe_profile
ikc_register ikc_unregister ikc_shutdown
poe_run_event poe_event_loop_extension
poe_dispatch_pending_async_events
poe_server_state poe_http_server_state poe_debug poe_http_debug
poe_http_test_run
@@ -133,7 +136,7 @@
{ 'DIR' => '.*', 'SESSION' => $session_name, 'EVENT' =>
'poe_http_server_state', },
],
);
- $self->log({level=>3},"Listening for HTTP Requests on
$self->{host}:$self->{options}{http_port}\n") if $self->{options}{poe_trace};
+ $self->log({level=>3},"Listening for HTTP Requests on
$self->{host}:$self->{options}{http_port}\n") if $self->{poe_trace};
&App::sub_exit() if ($App::trace);
}
@@ -350,7 +353,7 @@
### POE state dumping - Currently commented out because it doesn't gain us
much
### in the way of visibility, and POE::API::Peek is a CPAN pain
### UNCOMMENT THIS IF YOU NEED IT, DEPENDS ON A PAINFUL LIBRARY
- if ($self->{options}{poe_trace}) {
+ if ($self->{poe_peek}) {
App->use("POE::API::Peek");
my $api = POE::API::Peek->new();
my @queue = $api->event_queue_dump();
@@ -459,8 +462,9 @@
sub dispatch_pending_async_events {
&App::sub_entry if ($App::trace);
my ($self, $max_events) = @_;
+ $self->profile_start("dispatch_pending_async_events") if
$self->{poe_profile};
my $t0 = [gettimeofday];
- $self->log({level=>3},"dispatch_pending_async_events enter:
max_events=[$max_events]\n") if $self->{options}{poe_trace};
+ $self->log({level=>3},"dispatch_pending_async_events enter:
max_events=[$max_events]\n") if $self->{poe_trace};
$max_events ||= 9999;
my $pending_async_events = $self->{pending_async_events};
@@ -497,7 +501,8 @@
}
}
- $self->log({level=>3},"dispatch_pending_async_events exit:
events_occurred=[$events_occurred] time=[" . sprintf("%.4f", tv_interval($t0,
[gettimeofday])) . "]\n") if $self->{options}{poe_trace};
+ $self->log({level=>3},"dispatch_pending_async_events exit:
events_occurred=[$events_occurred] time=[" . sprintf("%.4f", tv_interval($t0,
[gettimeofday])) . "]\n") if $self->{poe_trace};
+ $self->profile_stop("dispatch_pending_async_events") if
$self->{poe_profile};
&App::sub_exit($events_occurred) if ($App::trace);
return($events_occurred);
}
@@ -519,6 +524,7 @@
sub send_async_event_now {
&App::sub_entry if ($App::trace);
my ($self, $event, $callback_event) = @_;
+ $self->profile_start("send_async_event_now") if $self->{poe_profile};
if ($event->{destination} eq "in_process") {
my $event_token = $self->send_async_event_in_process($event,
$callback_event);
@@ -553,6 +559,7 @@
my $runtime_event_token = $pid;
$self->{running_async_event}{$runtime_event_token} = [ $event,
$callback_event ];
}
+ $self->profile_stop("send_async_event_now") if $self->{poe_profile};
&App::sub_exit() if ($App::trace);
}
=head2 wait_for_event()
@@ -785,7 +792,7 @@
my (@args);
@args = @$args if (ref($args) eq "ARRAY");
@args = ($args) if (!ref($args));
- $self->log({level=>3},"POE: _default: Entered an unhandled state ($state)
with args (@args)\n") if $self->{options}{poe_trace};
+ $self->log({level=>3},"POE: _default: Entered an unhandled state ($state)
with args (@args)\n") if $self->{poe_trace};
&App::sub_exit() if ($App::trace);
}
@@ -814,6 +821,7 @@
# don't start kicking off async events until we give the nodes a chance to
register themselves
$kernel->delay_set("poe_event_loop_extension", 5) if
(!$self->{disable_event_loop_extensions});
$kernel->delay_set("poe_alarm", 5);
+ $kernel->delay_set("poe_profile", $self->{poe_profile}) if
($self->{poe_profile});
&App::sub_exit() if ($App::trace);
}
@@ -916,7 +924,8 @@
sub poe_alarm {
&App::sub_entry if ($App::trace);
my ( $self, $kernel, $heap ) = @_[ OBJECT, KERNEL, HEAP ];
- $self->log({level=>3},"poe_alarm enter\n") if $self->{options}{poe_trace};
+ $self->profile_start("poe_alarm") if $self->{poe_profile};
+ $self->log({level=>3},"poe_alarm enter\n") if $self->{poe_trace};
my $main_service = $self->{main_service};
@@ -945,7 +954,7 @@
### call some POE profile dump functions, only happens when ENV variables
### POE_TRACE_PROFILE=1 POE_TRACE_STATISTICS=1
- if ($self->{options}{poe_trace}) {
+ if ($self->{poe_trace}) {
my %data = $kernel->stat_getdata();
for my $key (sort keys %data) {
$self->log({level=>3},"poe_alarm: poe_statistics [" .
sprintf("%20s : %s", $key, $data{$key}) . "]\n");
@@ -953,7 +962,36 @@
$kernel->stat_show_profile();
}
- $self->log({level=>3},"poe_alarm exit: events_occurred[$events_occurred]
sec_until_next_event[$sec_until_next_event]\n") if $self->{options}{poe_trace};
+ $self->log({level=>3},"poe_alarm exit: events_occurred[$events_occurred]
sec_until_next_event[$sec_until_next_event]\n") if $self->{poe_trace};
+ $self->profile_stop("poe_alarm") if $self->{poe_profile};
+ &App::sub_exit() if ($App::trace);
+}
+
+sub poe_profile {
+ &App::sub_entry if ($App::trace);
+ my ( $self, $kernel, $heap ) = @_[ OBJECT, KERNEL, HEAP ];
+
+ my $poe_profile = $self->{poe_profile};
+ if ($poe_profile) {
+ $self->{poe_profile_id} = $kernel->delay_set("poe_profile",
$poe_profile);
+ my $profile_stats = $self->profile_stats();
+ $self->log("PROFILE: cumultime count avgtime mintime maxtime
key\n");
+ my ($stats);
+ foreach my $key (sort { $profile_stats->{$b}{cumul_time} <=>
$profile_stats->{$a}{cumul_time} } keys %$profile_stats) {
+ $stats = $profile_stats->{$key};
+ if ($stats->{count}) {
+ $self->log("PROFILE: %10.4f %10d %8.4f %8.4f %8.4f %s\n",
+ $stats->{cumul_time},
+ $stats->{count},
+ $stats->{cumul_time}/$stats->{count},
+ $stats->{min_time},
+ $stats->{max_time},
+ $key);
+ }
+ }
+ $self->profile_clear();
+ }
+
&App::sub_exit() if ($App::trace);
}
@@ -961,13 +999,14 @@
sub poe_shutdown {
&App::sub_entry if ($App::trace);
my ( $self, $kernel, $session, $heap ) = @_[ OBJECT, KERNEL, SESSION, HEAP
];
+ $self->profile_start("poe_shutdown") if $self->{poe_profile};
### Abort all running async events
for my $event_token (keys %{$self->{running_async_event}}) {
### We can't use the normal abort_async_event
### because POE and IKC are shutting down shortly
$self->_abort_running_async_event($event_token);
- $self->log({level=>3},"poe_shutdown: abort running events :
event_token=[$event_token]\n") if $self->{options}{poe_trace};
+ $self->log({level=>3},"poe_shutdown: abort running events :
event_token=[$event_token]\n") if $self->{poe_trace};
}
### Clear your alias
@@ -985,6 +1024,7 @@
### Shut down POE IKC
$kernel->post('IKC', 'shutdown');
+ $self->profile_stop("poe_shutdown") if $self->{poe_profile};
&App::sub_exit() if ($App::trace);
return;
}
@@ -992,19 +1032,22 @@
sub poe_dispatch_pending_async_events {
&App::sub_entry if ($App::trace);
my ( $self, $kernel, $heap, $arg ) = @_[ OBJECT, KERNEL, HEAP, ARG0 ];
- $self->log({level=>3},"POE: poe_dispatch_pending_async_events enter\n") if
$self->{options}{poe_trace};
+ $self->profile_start("poe_dispatch_pending_async_events") if
$self->{poe_profile};
+ $self->log({level=>3},"POE: poe_dispatch_pending_async_events enter\n") if
$self->{poe_trace};
$self->poe_yield_acknowledged("poe_dispatch_pending_async_events");
my $events_occurred = $self->dispatch_pending_async_events();
- $self->log({level=>3},"POE: poe_dispatch_pending_async_events exit:
events_occurred[$events_occurred]\n") if $self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_dispatch_pending_async_events exit:
events_occurred[$events_occurred]\n") if $self->{poe_trace};
+ $self->profile_stop("poe_dispatch_pending_async_events") if
$self->{poe_profile};
&App::sub_exit() if ($App::trace);
}
sub poe_event_loop_extension {
&App::sub_entry if ($App::trace);
my ( $self, $kernel, $heap ) = @_[ OBJECT, KERNEL, HEAP ];
- $self->log({level=>3},"POE: poe_event_loop_extension enter\n") if
$self->{options}{poe_trace};
+ $self->profile_start("poe_event_loop_extension") if $self->{poe_profile};
+ $self->log({level=>3},"POE: poe_event_loop_extension enter\n") if
$self->{poe_trace};
$self->poe_yield_acknowledged("poe_event_loop_extension");
my $event_loop_extensions = $self->{event_loop_extensions};
@@ -1024,7 +1067,8 @@
$self->poe_yield($kernel, "poe_event_loop_extension");
}
- $self->log({level=>3},"POE: poe_event_loop_extension exit:
event_loop_extensions[" . @$event_loop_extensions . "]
async_events_added[$async_events_added]\n") if $self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_event_loop_extension exit:
event_loop_extensions[" . @$event_loop_extensions . "]
async_events_added[$async_events_added]\n") if $self->{poe_trace};
+ $self->profile_stop("poe_event_loop_extension") if $self->{poe_profile};
&App::sub_exit() if ($App::trace);
}
@@ -1040,21 +1084,23 @@
sub poe_run_event {
&App::sub_entry if ($App::trace);
my ( $self, $kernel, $heap, $event ) = @_[ OBJECT, KERNEL, HEAP, ARG0 ];
- $self->log({level=>3},"POE: poe_run_event enter\n") if
$self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_run_event enter\n") if $self->{poe_trace};
my ($event_str);
my $args = $event->{args} || [];
my $args_str = join(",", @$args);
if ($event->{name}) {
my $service_type = $event->{service_type} || "SessionObject";
- $event_str =
"$service_type($event->{name}).$event->{method}($args_str)";
+ $event_str = "$service_type($event->{name}).$event->{method}";
}
else {
- $event_str = "$event->{method}($args_str)";
+ $event_str = "$event->{method}";
}
+ $self->profile_start("poe_run_event: $event_str") if $self->{poe_profile};
$self->send_event($event);
- $self->log({level=>3},"POE: poe_run_event exit: event[$event_str]\n") if
$self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_run_event exit:
event[$event_str($args_str)]\n") if $self->{poe_trace};
+ $self->profile_stop("poe_run_event: $event_str") if $self->{poe_profile};
&App::sub_exit() if ($App::trace);
}
@@ -1062,13 +1108,15 @@
sub poe_enqueue_async_event {
&App::sub_entry if ($App::trace);
my ($self, $kernel, $args) = @_[OBJECT, KERNEL, ARG0];
- $self->log({level=>3},"POE: poe_enqueue_async_event enter\n") if
$self->{options}{poe_trace};
+ $self->profile_start("poe_enqueue_async_event") if $self->{poe_profile};
+ $self->log({level=>3},"POE: poe_enqueue_async_event enter\n") if
$self->{poe_trace};
my ($sender, $event, $callback_event) = @$args;
my $runtime_event_token = $self->send_async_event($event, { method =>
"async_event_finished", args => [ $sender, $event, $callback_event ], });
$event->{event_token} = $runtime_event_token;
- $self->log({level=>3},"POE: poe_enqueue_async_event exit:
event[$event->{name}.$event->{method} token=$event->{event_token}]
runtime_event_token[$runtime_event_token]\n") if $self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_enqueue_async_event exit:
event[$event->{name}.$event->{method} token=$event->{event_token}]
runtime_event_token[$runtime_event_token]\n") if $self->{poe_trace};
+ $self->profile_stop("poe_enqueue_async_event") if $self->{poe_profile};
&App::sub_exit([$runtime_event_token, [$event, $callback_event]]) if
($App::trace);
return([$runtime_event_token, [$event, $callback_event]]);
}
@@ -1077,12 +1125,14 @@
sub poe_enqueue_async_event_finished {
&App::sub_entry if ($App::trace);
my ($self, $kernel, $return_values) = @_[OBJECT, KERNEL, ARG0];
- $self->log({level=>3},"POE: poe_enqueue_async_event_finished enter\n") if
$self->{options}{poe_trace};
+ $self->profile_start("poe_enqueue_async_event_finished") if
$self->{poe_profile};
+ $self->log({level=>3},"POE: poe_enqueue_async_event_finished enter\n") if
$self->{poe_trace};
my ($runtime_event_token, $async_event) = @$return_values;
$self->{running_async_event}{$runtime_event_token} = $async_event;
- $self->log({level=>3},"POE: poe_enqueue_async_event_finished exit:
event[$async_event->[0]{name}.$async_event->[0]{method} =>
$runtime_event_token]\n") if $self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_enqueue_async_event_finished exit:
event[$async_event->[0]{name}.$async_event->[0]{method} =>
$runtime_event_token]\n") if $self->{poe_trace};
+ $self->profile_stop("poe_enqueue_async_event_finished") if
$self->{poe_profile};
&App::sub_exit() if ($App::trace);
}
@@ -1090,6 +1140,7 @@
sub async_event_finished {
&App::sub_entry if ($App::trace);
my ($self, $sender, $event, $callback_event) = @_;
+ $self->profile_start("async_event_finished") if $self->{poe_profile};
my $runtime_event_token = $event->{event_token};
my $remote_server_name = "poe_${sender}";
@@ -1101,6 +1152,7 @@
$kernel->post("IKC", "post",
"poe://$remote_server_name/$remote_session_alias/$remote_session_state",
[ $runtime_event_token, $callback_event->{args} ]);
+ $self->profile_stop("async_event_finished") if $self->{poe_profile};
&App::sub_exit() if ($App::trace);
}
@@ -1108,13 +1160,14 @@
sub poe_remote_async_event_finished {
&App::sub_entry if ($App::trace);
my ($self, $kernel, $args) = @_[OBJECT, KERNEL, ARG0];
- $self->log({level=>3},"POE: poe_remote_async_event_finished enter\n") if
$self->{options}{poe_trace};
+ $self->profile_start("poe_remote_async_event_finished") if
$self->{poe_profile};
+ $self->log({level=>3},"POE: poe_remote_async_event_finished enter\n") if
$self->{poe_trace};
my ($runtime_event_token, $callback_args) = @$args;
my $async_event = $self->{running_async_event}{$runtime_event_token};
if ($async_event) {
my ($event, $callback_event) = @$async_event;
- $self->log({level=>3},"POE: poe_remote_async_event_finished :
($event->{name}.$event->{method} => $runtime_event_token)\n") if
$self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_remote_async_event_finished :
($event->{name}.$event->{method} => $runtime_event_token)\n") if
$self->{poe_trace};
delete $self->{running_async_event}{$runtime_event_token};
my $destination = $event->{destination} || "local";
@@ -1140,18 +1193,21 @@
}
}
- $self->log({level=>3},"POE: poe_remote_async_event_finished exit\n") if
$self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_remote_async_event_finished exit\n") if
$self->{poe_trace};
+ $self->profile_stop("poe_remote_async_event_finished") if
$self->{poe_profile};
&App::sub_exit() if ($App::trace);
}
sub poe_server_state {
&App::sub_entry if ($App::trace);
my ( $self, $kernel, $heap ) = @_[ OBJECT, KERNEL, HEAP ];
- $self->log({level=>3},"POE: poe_server_state enter\n") if
$self->{options}{poe_trace};
+ $self->profile_start("poe_server_state") if $self->{poe_profile};
+ $self->log({level=>3},"POE: poe_server_state enter\n") if
$self->{poe_trace};
my $server_state = $self->state();
- $self->log({level=>3},"POE: poe_server_state exit\n") if
$self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_server_state exit\n") if
$self->{poe_trace};
+ $self->profile_stop("poe_server_state") if $self->{poe_profile};
&App::sub_exit($server_state) if ($App::trace);
return $server_state;
}
@@ -1159,7 +1215,8 @@
sub poe_http_server_state {
&App::sub_entry if ($App::trace);
my ( $self, $kernel, $heap, $request, $response ) = @_[ OBJECT, KERNEL,
HEAP, ARG0, ARG1 ];
- $self->log({level=>3},"POE: poe_http_server_state enter\n") if
$self->{options}{poe_trace};
+ $self->profile_start("poe_http_server_state") if $self->{poe_profile};
+ $self->log({level=>3},"POE: poe_http_server_state enter\n") if
$self->{poe_trace};
my $server_state = $kernel->call( $self->{poe_session_name},
'poe_server_state' );
### Build the response.
@@ -1169,7 +1226,8 @@
### Signal that the request was handled okay.
$kernel->post( $self->{poe_kernel_http_name}, 'DONE', $response );
- $self->log({level=>3},"POE: poe_http_server_state exit\n") if
$self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_http_server_state exit\n") if
$self->{poe_trace};
+ $self->profile_stop("poe_http_server_state") if $self->{poe_profile};
&App::sub_exit(RC_OK) if ($App::trace);
return RC_OK;
}
@@ -1177,11 +1235,13 @@
sub poe_debug {
&App::sub_entry if ($App::trace);
my ( $self, $kernel, $heap ) = @_[ OBJECT, KERNEL, HEAP ];
- $self->log({level=>3},"POE: poe_debug enter\n") if
$self->{options}{poe_trace};
+ $self->profile_start("poe_debug") if $self->{poe_profile};
+ $self->log({level=>3},"POE: poe_debug enter\n") if $self->{poe_trace};
my $debug = $self->debug();
- $self->log({level=>3},"POE: poe_debug exit\n") if
$self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_debug exit\n") if $self->{poe_trace};
+ $self->profile_stop("poe_debug") if $self->{poe_profile};
&App::sub_exit($debug) if ($App::trace);
return $debug;
}
@@ -1189,6 +1249,7 @@
sub poe_http_debug {
&App::sub_entry if ($App::trace);
my ( $self, $kernel, $heap, $request, $response ) = @_[ OBJECT, KERNEL,
HEAP, ARG0, ARG1 ];
+ $self->profile_start("poe_http_debug") if $self->{poe_profile};
$self->log({level=>3},"POE: poe_http_debug enter\n");
my $debug = $kernel->call( $self->{poe_session_name}, 'poe_debug' );
@@ -1199,7 +1260,8 @@
### Signal that the request was handled okay.
$kernel->post( $self->{poe_kernel_http_name}, 'DONE', $response );
- $self->log({level=>3},"POE: poe_http_debug exit\n") if
$self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_http_debug exit\n") if $self->{poe_trace};
+ $self->profile_stop("poe_http_debug") if $self->{poe_profile};
&App::sub_exit(RC_OK) if ($App::trace);
return RC_OK;
}
@@ -1207,7 +1269,8 @@
sub poe_http_test_run {
&App::sub_entry if ($App::trace);
my ( $self, $kernel, $heap, $request, $response ) = @_[ OBJECT, KERNEL,
HEAP, ARG0, ARG1 ];
- $self->log({level=>3},"POE: poe_http_test_run enter\n") if
$self->{options}{poe_trace};
+ $self->profile_start("poe_http_test_run") if $self->{poe_profile};
+ $self->log({level=>3},"POE: poe_http_test_run enter\n") if
$self->{poe_trace};
my $event = {
service_type => "SessionObject",
@@ -1225,7 +1288,8 @@
# Signal that the request was handled okay.
$kernel->post( $self->{poe_kernel_http_name}, 'DONE', $response );
- $self->log({level=>3},"POE: poe_http_test_run exit\n") if
$self->{options}{poe_trace};
+ $self->log({level=>3},"POE: poe_http_test_run exit\n") if
$self->{poe_trace};
+ $self->profile_stop("poe_http_test_run") if $self->{poe_profile};
&App::sub_exit(RC_OK) if ($App::trace);
return RC_OK;
}
