add EXPERIMENTAL support for Server-Timing header

mojolicious · Feb 10, 2018 · 1e5b53b · 1e5b53b
1 parent 55953f0
commit 1e5b53b
Show file tree

Hide file tree

Showing 7 changed files with 90 additions and 12 deletions.
diff --git a/Changes b/Changes
@@ -1,5 +1,8 @@
 
-7.65  2018-02-08
+7.65  2018-02-10
+  - Added EXPERIMENTAL profile->elapsed, profile->server_timing and
+    profile->start helpers to Mojolicious::Plugin::DefaultHelpers.
+  - Added EXPERIMENTAL server_timing method to Mojo::Headers.
   - Added support for new HTTP status code.
 
 7.64  2018-02-07

diff --git a/lib/Mojo/Headers.pm b/lib/Mojo/Headers.pm
@@ -16,8 +16,8 @@ my %NAMES = map { lc() => $_ } (
   qw(Last-Modified Link Location Origin Proxy-Authenticate),
   qw(Proxy-Authorization Range Sec-WebSocket-Accept Sec-WebSocket-Extensions),
   qw(Sec-WebSocket-Key Sec-WebSocket-Protocol Sec-WebSocket-Version Server),
-  qw(Set-Cookie Status Strict-Transport-Security TE Trailer Transfer-Encoding),
-  qw(Upgrade User-Agent Vary WWW-Authenticate)
+  qw(Server-Timing Set-Cookie Status Strict-Transport-Security TE Trailer),
+  qw(Transfer-Encoding Upgrade User-Agent Vary WWW-Authenticate)
 );
 for my $header (keys %NAMES) {
   my $name = $header;
@@ -609,6 +609,14 @@ header from L<RFC 6455|http://tools.ietf.org/html/rfc6455>.
 
 Get or replace current header value, shortcut for the C<Server> header.
 
+=head2 server_timing
+
+  my $timing = $headers->server_timing;
+  $headers   = $headers->server_timing('app;desc=Mojolicious;dur=0.0001');
+
+Get or replace current header value, shortcut for the C<Server-Timing> header.
+Note that this method is EXPERIMENTAL and might change without warning!
+
 =head2 set_cookie
 
   my $cookie = $headers->set_cookie;

diff --git a/lib/Mojolicious.pm b/lib/Mojolicious.pm
@@ -18,7 +18,6 @@ use Mojolicious::Static;
 use Mojolicious::Types;
 use Mojolicious::Validator;
 use Scalar::Util ();
-use Time::HiRes  ();
 
 has commands => sub {
   my $commands = Mojolicious::Commands->new(app => shift);
@@ -129,7 +128,7 @@ sub dispatch {
     my $method = $req->method;
     my $path   = $req->url->path->to_abs_string;
     $self->log->debug(qq{$method "$path"});
-    $stash->{'mojo.started'} = [Time::HiRes::gettimeofday];
+    $c->helpers->profile->start('mojo.timer');
   }
 
   # Routes

diff --git a/lib/Mojolicious/Controller.pm b/lib/Mojolicious/Controller.pm
@@ -8,7 +8,6 @@ use Mojo::URL;
 use Mojo::Util;
 use Mojolicious::Routes::Match;
 use Scalar::Util ();
-use Time::HiRes  ();
 
 has [qw(app tx)];
 has match =>
@@ -202,9 +201,7 @@ sub rendered {
 
     # Disable auto rendering and stop timer
     my $app = $self->render_later->app;
-    if (my $started = delete $stash->{'mojo.started'}) {
-      my $elapsed
-        = Time::HiRes::tv_interval($started, [Time::HiRes::gettimeofday()]);
+    if (defined(my $elapsed = $self->helpers->profile->elapsed('mojo.timer'))) {
       my $rps  = $elapsed == 0 ? '??' : sprintf '%.3f', 1 / $elapsed;
       my $code = $res->code;
       my $msg  = $res->message || $res->default_message($code);

diff --git a/lib/Mojolicious/Plugin/DefaultHelpers.pm b/lib/Mojolicious/Plugin/DefaultHelpers.pm
@@ -6,6 +6,7 @@ use Mojo::Collection;
 use Mojo::Exception;
 use Mojo::IOLoop;
 use Mojo::Util qw(dumper hmac_sha1_sum steady_time);
+use Time::HiRes qw(gettimeofday tv_interval);
 use Scalar::Util 'blessed';
 
 sub register {
@@ -41,6 +42,10 @@ sub register {
   $app->helper('reply.exception' => sub { _development('exception', @_) });
   $app->helper('reply.not_found' => sub { _development('not_found', @_) });
 
+  $app->helper('profile.elapsed'       => \&_profile_elapsed);
+  $app->helper('profile.server_timing' => \&_profile_server_timing);
+  $app->helper('profile.start'         => \&_profile_start);
+
   $app->helper(ua => sub { shift->app->ua });
 }
 
@@ -143,6 +148,25 @@ sub _is_fresh {
   return $c->app->static->is_fresh($c, \%options);
 }
 
+sub _profile_elapsed {
+  my ($c, $name) = @_;
+  return undef unless my $started = $c->stash->{'mojo.profile'}{$name};
+  return tv_interval($started, [gettimeofday()]);
+}
+
+sub _profile_server_timing {
+  my ($c, $metric, $desc, $name) = @_;
+  my $value = $metric;
+  $value .= qq{;desc="$desc"} if $desc;
+  if ($name && (my $d = _profile_elapsed($c, $name))) { $value .= ";dur=$d" }
+  $c->res->headers->append('Server-Timing' => $value);
+}
+
+sub _profile_start {
+  my ($c, $name) = @_;
+  $c->stash->{'mojo.profile'}{$name} = [gettimeofday];
+}
+
 sub _static {
   my ($c, $file) = @_;
   return !!$c->rendered if $c->app->static->serve($c, $file);
@@ -461,6 +485,31 @@ Alias for L<Mojolicious::Controller/"stash">.
 
   %= stash('name') // 'Somebody'
 
+=head2 profile->elapsed
+
+  my $elapsed = $c->timer->elapsed('foo');
+
+Return fractional number of seconds since named timstamp has been created with
+L</"profile-E<gt>start"> or C<undef> if no such timestamp exists. Note that this
+helper is EXPERIMENTAL and might change without warning!
+
+=head2 profile->server_timing
+
+  $c->profile->server_timing('app');
+  $c->profile->server_timing('app', 'Some Description');
+  $c->profile->server_timing('app', 'Some Description', 'foo');
+
+Create C<Server-Timing> header with or without named timestamp created with
+L</"profile-E<gt>start">. Note that this helper is EXPERIMENTAL and might change
+without warning! 
+
+=head2 profile->start
+
+  $c->profile->start('foo');
+
+Create named timestamp. Note that this helper is EXPERIMENTAL and might change
+without warning!
+
 =head2 title
 
   %= title

diff --git a/t/mojo/headers.t b/t/mojo/headers.t
@@ -94,9 +94,10 @@ is $headers->sec_websocket_protocol('foo')->sec_websocket_protocol, 'foo',
   'right value';
 is $headers->sec_websocket_version('foo')->sec_websocket_version, 'foo',
   'right value';
-is $headers->server('foo')->server,         'foo', 'right value';
-is $headers->set_cookie('foo')->set_cookie, 'foo', 'right value';
-is $headers->status('foo')->status,         'foo', 'right value';
+is $headers->server('foo')->server,               'foo', 'right value';
+is $headers->server_timing('foo')->server_timing, 'foo', 'right value';
+is $headers->set_cookie('foo')->set_cookie,       'foo', 'right value';
+is $headers->status('foo')->status,               'foo', 'right value';
 is $headers->strict_transport_security('foo')->strict_transport_security,
   'foo', 'right value';
 is $headers->te('foo')->te,                               'foo', 'right value';

diff --git a/t/mojolicious/lite_app.t b/t/mojolicious/lite_app.t
@@ -11,6 +11,7 @@ use Mojo::Cookie::Response;
 use Mojo::IOLoop;
 use Mojolicious::Lite;
 use Test::Mojo;
+use Time::HiRes 'usleep';
 
 # Missing plugin
 eval { plugin 'does_not_exist' };
@@ -444,6 +445,20 @@ get '/dynamic/inline' => sub {
   $c->render(inline => 'dynamic inline ' . $dynamic_inline++);
 };
 
+get '/profile' => sub {
+  my $c = shift;
+  $c->profile->start('foo');
+  $c->profile->start('bar');
+  usleep 1000;
+  my $foo = $c->profile->elapsed('foo');
+  my $bar = $c->profile->elapsed('bar');
+  $c->profile->server_timing('miss');
+  $c->profile->server_timing('dc',   'atl');
+  $c->profile->server_timing('test', 'Some Test', 'foo');
+  $c->profile->server_timing('app',  undef, 'foo');
+  $c->render(text => "Foo: $foo, Bar: $bar");
+};
+
 my $t = Test::Mojo->new;
 
 # Application is already available
@@ -1028,6 +1043,12 @@ $t->get_ok('/url_with/foo?foo=bar')->status_is(200)
 $t->get_ok('/dynamic/inline')->status_is(200)->content_is("dynamic inline 1\n");
 $t->get_ok('/dynamic/inline')->status_is(200)->content_is("dynamic inline 2\n");
 
+# Profiling
+$t->get_ok('/profile')->status_is(200)
+  ->header_like('Server-Timing' =>
+    qr/miss, dc;desc="atl", test;desc="Some Test";dur=[0-9.]+, app;dur=[0-9.]+/)
+  ->content_like(qr/Foo: [0-9.]+, Bar: [0-9.]+/);
+
 done_testing();
 
 __DATA__