[svn:p5ee] r7982 - p5ee/trunk/App-Context/lib/App/Context

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 %s[%s\@%s]\n",
+        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;