log elapsed time

I'm an idiot.  I say I won't do it, then I go and do it anyway.

Fortunately, in this case, the code and execution remain exactly the
same for people who do not set $GL_PERFLOGT in the rc file, so it's
tolerable.

<evil grin> People who want even more than this can contact Greg Lonnon
(see the mailing list archives at
http://groups.google.com/group/gitolite for an obfuscated but easy to
guess email address) ;-)

conf/example.gitolite.rc

@@ -71,6 +71,17 @@ $GL_LOGT="$GL_ADMINDIR/logs/gitolite-%y-%m.log";
 
 # --------------------------------------
 
+# location of the performance log files
+
+# uncomment and set this variable if you want performance logging
+#
+# perf log files are different from access log files; they store different
+# information, are not meant to be as long-lived, and so on
+
+# $GL_PERFLOGT="$GL_ADMINDIR/logs/perf-gitolite-%y-%m.log";
+
+# --------------------------------------
+
 # Please DO NOT change these three paths
 
 $GL_CONF="$GL_ADMINDIR/conf/gitolite.conf";

hooks/common/update

@@ -25,7 +25,7 @@ use warnings;
 #       common definitions
 # ----------------------------------------------------------------------------
 
-our ($GL_CONF_COMPILED, $UPDATE_CHAINS_TO);
+our ($GL_CONF_COMPILED, $UPDATE_CHAINS_TO, $GL_PERFLOGT);
 our %repos;
 
 # people with shell access should be allowed to bypass the update hook, simply

src/gitolite.pm

@@ -37,7 +37,7 @@ our $USERNAME_PATT=qr(^\@?[0-9a-zA-Z][0-9a-zA-Z._\@+-]*$);  # very simple patter
 our $REPOPATT_PATT=qr(^\@?[0-9a-zA-Z[][\\^.$|()[\]*+?{}0-9a-zA-Z._\@/-]*$);
 
 # these come from the RC file
-our ($REPO_UMASK, $GL_WILDREPOS, $GL_PACKAGE_CONF, $GL_PACKAGE_HOOKS, $REPO_BASE, $GL_CONF_COMPILED, $GL_BIG_CONFIG);
+our ($REPO_UMASK, $GL_WILDREPOS, $GL_PACKAGE_CONF, $GL_PACKAGE_HOOKS, $REPO_BASE, $GL_CONF_COMPILED, $GL_BIG_CONFIG, $GL_PERFLOGT);
 our %repos;
 our %groups;
 our %repo_config;
@@ -64,6 +64,24 @@ sub dbg {
     }
 }
 
+sub get_logfilename {
+    # this sub has a wee little side-effect; it sets $ENV{GL_TS}
+    my($template) = shift;
+
+    my ($s, $min, $h, $d, $m, $y) = (localtime)[0..5];
+    $y += 1900; $m++;               # usual adjustments
+    for ($s, $min, $h, $d, $m) {
+        $_ = "0$_" if $_ < 10;
+    }
+    $ENV{GL_TS} = "$y-$m-$d.$h:$min:$s";
+
+    # substitute template parameters and set the logfile name
+    $template =~ s/%y/$y/g;
+    $template =~ s/%m/$m/g;
+    $template =~ s/%d/$d/g;
+    return ($template);
+}
+
 sub log_it {
     my ($ip, $logmsg);
     open my $log_fh, ">>", $ENV{GL_LOG} or die "open log failed: $!\n";
@@ -608,6 +626,7 @@ sub setup_authkeys
 
     # command and options for authorized_keys
     my $AUTH_COMMAND="$bindir/gl-auth-command";
+    $AUTH_COMMAND="$bindir/gl-time $bindir/gl-auth-command" if $GL_PERFLOGT;
     my $AUTH_OPTIONS="no-port-forwarding,no-X11-forwarding,no-agent-forwarding,no-pty";
 
     # START

src/gl-auth-command

@@ -23,7 +23,7 @@ use warnings;
 # ----------------------------------------------------------------------------
 
 # these are set by the "rc" file
-our ($GL_LOGT, $GL_CONF_COMPILED, $REPO_BASE, $GIT_PATH, $REPO_UMASK, $GL_ADMINDIR, $RSYNC_BASE, $HTPASSWD_FILE, $GL_WILDREPOS, $GL_WILDREPOS_DEFPERMS, $GL_ADC_PATH, $SVNSERVE, $PROJECTS_LIST, $GL_SLAVE_MODE);
+our ($GL_LOGT, $GL_CONF_COMPILED, $REPO_BASE, $GIT_PATH, $REPO_UMASK, $GL_ADMINDIR, $RSYNC_BASE, $HTPASSWD_FILE, $GL_WILDREPOS, $GL_WILDREPOS_DEFPERMS, $GL_ADC_PATH, $SVNSERVE, $PROJECTS_LIST, $GL_SLAVE_MODE, $GL_PERFLOGT);
 # and these are set by gitolite.pm
 our ($R_COMMANDS, $W_COMMANDS, $REPONAME_PATT, $REPOPATT_PATT);
 our %repos;
@@ -82,19 +82,7 @@ $ENV{GL_GROUP_LIST} = join(" ", @ARGV) if @ARGV;
 #       logging, timestamp env vars
 # ----------------------------------------------------------------------------
 
-# timestamp
+$ENV{GL_LOG} = &get_logfilename($GL_LOGT);
-my ($s, $min, $h, $d, $m, $y) = (localtime)[0..5];
-$y += 1900; $m++;               # usual adjustments
-for ($s, $min, $h, $d, $m) {
-    $_ = "0$_" if $_ < 10;
-}
-$ENV{GL_TS} = "$y-$m-$d.$h:$min:$s";
-
-# substitute template parameters and set the logfile name
-$GL_LOGT =~ s/%y/$y/g;
-$GL_LOGT =~ s/%m/$m/g;
-$GL_LOGT =~ s/%d/$d/g;
-$ENV{GL_LOG} = $GL_LOGT;
 
 # ----------------------------------------------------------------------------
 #       sanity checks on SSH_ORIGINAL_COMMAND

src/gl-compile-conf

@@ -52,7 +52,7 @@ $Data::Dumper::Sortkeys = 1;
 open STDOUT, ">", "/dev/null" if (@ARGV and shift eq '-q');
 
 # these are set by the "rc" file
-our ($GL_ADMINDIR, $GL_CONF, $GL_KEYDIR, $GL_CONF_COMPILED, $REPO_BASE, $REPO_UMASK, $PROJECTS_LIST, $GIT_PATH, $GL_WILDREPOS, $GL_GITCONFIG_KEYS, $GL_GITCONFIG_WILD, $GL_PACKAGE_HOOKS, $GL_BIG_CONFIG, $GL_NO_DAEMON_NO_GITWEB, $GL_NO_CREATE_REPOS, $GL_NO_SETUP_AUTHKEYS);
+our ($GL_ADMINDIR, $GL_CONF, $GL_KEYDIR, $GL_CONF_COMPILED, $REPO_BASE, $REPO_UMASK, $PROJECTS_LIST, $GIT_PATH, $GL_WILDREPOS, $GL_GITCONFIG_KEYS, $GL_GITCONFIG_WILD, $GL_PACKAGE_HOOKS, $GL_BIG_CONFIG, $GL_NO_DAEMON_NO_GITWEB, $GL_NO_CREATE_REPOS, $GL_NO_SETUP_AUTHKEYS, $GL_PERFLOGT);
 # and these are set by gitolite.pm
 our ($REPONAME_PATT, $REPOPATT_PATT, $USERNAME_PATT, $ABRT, $WARN);
 

src/gl-install

@@ -5,7 +5,7 @@
 use strict;
 use warnings;
 
-our ($REPO_BASE, $GL_ADMINDIR, $GL_CONF, $GIT_PATH, $GL_PACKAGE_CONF, $GL_PACKAGE_HOOKS);
+our ($REPO_BASE, $GL_ADMINDIR, $GL_CONF, $GIT_PATH, $GL_PACKAGE_CONF, $GL_PACKAGE_HOOKS, $GL_PERFLOGT);
 
 # setup quiet mode if asked; please do not use this when running manually
 open STDOUT, ">", "/dev/null" if (@ARGV and shift eq '-q');

src/gl-setup-authkeys

@@ -24,6 +24,8 @@
 # All in all, unless it is shown to be quite inefficient, I'd much
 # prefer processing *all* keys each time there is a change.
 
+our ($GL_PERFLOGT);
+
 # setup
 my $bindir = $0;
 $bindir =~ s/\/[^\/]+$//;

src/gl-time

@@ -0,0 +1,40 @@
+#!/usr/bin/perl
+
+# this program is a performance measurement wrapper around anything that it is
+# called with; it's arg-1 becomes the program being measured, with arg-2
+# onwards being arg-1's arguments
+
+# sorta like the "time" command... hence the name :-)
+
+use strict;
+use warnings;
+
+use Time::HiRes qw(gettimeofday tv_interval);
+
+our ($GL_PERFLOGT);
+
+# rc file
+do "$ENV{HOME}/.gitolite.rc";
+    # this file is always in a fixed place; code in the main gitolite that
+    # seems to indicate it is not, is obsolete and needs to be fixed.
+
+# the common setup module is in the same directory as this running program is
+my $bindir = $0;
+$bindir =~ s/\/[^\/]+$//;
+$bindir = "$ENV{PWD}/$bindir" unless $bindir =~ /^\//;
+require "$bindir/gitolite.pm";
+
+# ---------------------------------------------------------------
+
+my $starttime = [gettimeofday];
+
+my $pgm = shift;
+my $returncode = system($pgm, @ARGV);
+$returncode >>= 8;
+$ENV{GL_USER} = shift;
+
+my $elapsedtime = tv_interval($starttime);
+
+$ENV{GL_LOG} = &get_logfilename($GL_PERFLOGT);
+# log_it logs to $ENV{GL_LOG}
+&log_it("", "$elapsedtime\trc=$returncode");