Author: spadkins
Date: Thu Oct 26 06:17:20 2006
New Revision: 7982
Modified:
p5ee/trunk/App-Context/lib/App/Context/HTTP.pm
Log:
add UI time log, activated with app.Context.timer option
Modified: p5ee/trunk/App-Context/lib/App/Context/HTTP.pm
==============================================================================
--- p5ee/trunk/App-Context/lib/App/Context/HTTP.pm (original)
+++ p5ee/trunk/App-Context/lib/App/Context/HTTP.pm Thu Oct 26 06:17:20 2006
@@ -12,6 +12,8 @@
@ISA = ( "App::Context" );
use App::UserAgent;
+use Time::HiRes qw(gettimeofday tv_interval);
+use Date::Format;
use strict;
@@ -132,6 +134,9 @@
&App::sub_entry if ($App::trace);
my ($self) = @_;
+ my $timer = $self->{options}{"app.Context.timer"};
+ my $content_description = "Unknown";
+ $self->start_timer() if ($timer);
eval {
$self->dispatch_events_begin();
@@ -143,41 +148,36 @@
while ($#$events > -1) {
$event = shift(@$events);
($service, $name, $method, $args) = @$event;
- #if ($service eq "SessionObject") {
- # $self->call($service, $name, $method, $args);
- #}
- #else {
- $results = $self->call($service, $name, $method, $args);
- #$results = [ $results ] if (!ref($results));
- # $display_current_widget = 0;
- #}
+ $results = $self->call($service, $name, $method, $args);
+ $args = join(",", @$args) if (ref($args) eq "ARRAY");
+ $self->lap_timer("$service($name).$method($args)") if ($timer);
}
- #if ($display_current_widget) { }
- #if (! defined $results) {
- my $type = $self->so_get("default","ctype","SessionObject");
- $name = $self->so_get("default","cname");
- #if ($xyz) {
- $results = $self->service($type, $name);
- #}
- #}
+ my $type = $self->so_get("default","ctype","SessionObject");
+ $name = $self->so_get("default","cname");
+ $results = $self->service($type, $name);
my $response = $self->response();
my $ref = ref($results);
if (!$ref || $ref eq "ARRAY" || $ref eq "HASH") {
$response->content($results);
+ $content_description = "results [$ref]";
}
elsif ($results->isa("App::Service")) {
$response->content($results->content());
$response->content_type($results->content_type());
+ $content_description = $results->content_description();
}
else {
$response->content($results->internals());
+ $content_description = "$type($name).internals()";
}
$self->send_response();
+ $self->stop_timer($content_description) if ($timer);
};
if ($@) {
$self->send_error($@);
+ $self->stop_timer("ERROR [$content_description]: $@") if ($timer); #
before we shut down database connections
}
if ($self->{options}{debug_context}) {
@@ -524,5 +524,83 @@
return $user;
}
+#04899 000.000000 000.000000 Start 2006/06/28 21:56:52.827139 GET
[222.252.72.65] localhost
+#04899 000.023569 000.023569 MarketVision[8] Controller code loaded
+#04899 000.394568 000.418137 MarketVision[666] code loaded, vars initialized
+#04899 000.025432 000.443569 MarketVision[671] CGI vars read [handaeww]
[handaeww]
+#04899 000.000243 000.443812 MarketVision[673] announcement checked
+#04899 000.011994 000.455806 MarketVision[676] db open
+#04899 000.328063 000.783869 MarketVision[689] Context+Repository open
+#04899 000.115011 000.898880 MarketVision[706] got orgs
+#04899 000.054074 000.952954 Controller.pm[262] screen transitions presel=3
sel=3 prescreen=main :
+#04899 000.000101 000.953055 Controller.pm[292] none executed []
+#04899 001.501768 002.454823 Controller.pm[300] screen shown [main]
+#04899 000.000084 002.454907 MarketVision[771] dispatched events
+#04899 000.000560 002.455467 MarketVision[787] db disconnected.
+#04899 000.000050 002.455517 End 2006/06/28 21:56:55.282656 usr0.8s sys0.1s
ops:0
+
+sub start_timer {
+ &App::sub_entry if ($App::trace);
+ my ($self) = @_;
+
+ my $app = $self->{options}{app} || "app";
+ open(App::Context::TIMELOG, ">> $app.log");
+
+ #my $old_handle = select(App::Context::TIMELOG); # "select" TIMELOG and
save previously selected handle
+ #$| = 1; # set to non-buffered
output (perform flush) after each write
+ #select ($old_handle); # restore previously
selected handle
+
+ my $time = [ gettimeofday ];
+ $self->{time_start} = $time;
+ $self->{time_lap} = $time;
+
+ printf App::Context::TIMELOG "$$ %010.6f %010.6f Start : %s [EMAIL
PROTECTED]",
+ 0, 0,
+ time2str("%Y-%m-%d %H:%M:%S",$time->[0]),
+ $ENV{REQUEST_METHOD},
+ $ENV{REMOTE_USER},
+ $ENV{REMOTE_ADDR};
+
+ &App::sub_exit() if ($App::trace);
+}
+
+sub lap_timer {
+ &App::sub_entry if ($App::trace);
+ my ($self, $desc) = @_;
+
+ my $time = [ gettimeofday ];
+
+ printf App::Context::TIMELOG "$$ %010.6f %010.6f * $desc\n",
+ tv_interval($self->{time_start}, $time),
+ tv_interval($self->{time_lap}, $time);
+
+ $self->{time_lap} = $time;
+
+ &App::sub_exit() if ($App::trace);
+}
+
+sub stop_timer {
+ &App::sub_entry if ($App::trace);
+ my ($self, $desc) = @_;
+
+ my $time = [ gettimeofday ];
+
+ printf App::Context::TIMELOG "$$ %010.6f %010.6f End : $desc\n",
+ tv_interval($self->{time_start}, $time),
+ tv_interval($self->{time_lap}, $time);
+
+ # time2str("%Y-%m-%d %H:%M:%S",$time->[0]),
+ # $ENV{REQUEST_METHOD},
+ # $ENV{REMOTE_USER},
+ # $ENV{REMOTE_ADDR};
+
+ delete $self->{time_start};
+ delete $self->{time_lap};
+
+ close(App::Context::TIMELOG);
+
+ &App::sub_exit() if ($App::trace);
+}
+
1;
