summaryrefslogtreecommitdiff
path: root/util
diff options
context:
space:
mode:
authorYorhel <git@yorhel.nl>2020-05-28 13:51:53 +0200
committerYorhel <git@yorhel.nl>2020-05-28 14:02:44 +0200
commit002f165ed4823b7563e7443526d907d27b5b431b (patch)
tree5b38e850c47535587469586ac039ddd4211ad1c4 /util
parentf7d7e3576a68f1de6d2eec2ef4f8f7a4c982372f (diff)
Add sampling-based trace logging
This is intended to get some stats about resource usage (which pages/modules are requested often, how much time do they take, etc) to reduce server load and find pages to optimize, and to track usage of Elm modules in order to see how many pageviews actually need them so that I can (hopefully) create smaller JS bundles for most pages. The logging *should* not include any personally identifiable information, but paths and query strings could still reveal more information than necessary. Trace logging is intended to only be enabled for short periods of time or with low sample rates in order to avoid slowing down the server with too much logging. I also don't intend to keep the data around for longer than necessary. I'm not providing SQL migration scripts for these, this feature is going to require custom querying anyway.
Diffstat (limited to 'util')
-rwxr-xr-xutil/vndb.pl43
1 files changed, 43 insertions, 0 deletions
diff --git a/util/vndb.pl b/util/vndb.pl
index 3eafe5af..5c6d5a6a 100755
--- a/util/vndb.pl
+++ b/util/vndb.pl
@@ -4,6 +4,7 @@ use v5.24;
use warnings;
use Cwd 'abs_path';
use TUWF ':html_';
+use Time::HiRes 'time';
$|=1; # Disable buffering on STDOUT, otherwise vndb-dev-server.pl won't pick up our readyness notification.
@@ -64,6 +65,8 @@ TUWF::hook before => sub {
# Use a 'SameSite=Strict' cookie to determine whether this page was loaded from internal or external.
# Ought to be more reliable than checking the Referer header, but it's unfortunately a bit uglier.
tuwf->resCookie(samesite => 1, httponly => 1, samesite => 'Strict') if !tuwf->samesite;
+
+ tuwf->req->{trace_start} = time if config->{trace_log};
};
@@ -109,8 +112,48 @@ sub TUWF::Object::resDenied {
}
+# Intercept TUWF::any() and TUWF::register() to figure out which module is processing the request.
+if(config->{trace_log}) {
+ my sub wrap {
+ my $f = shift;
+ sub {
+ my $i = 0;
+ my $loc = ['',0];
+ while(my($pack, undef, $line) = caller($i++)) {
+ if($pack !~ '^(?:main|TUWF|VNWeb::Elm)') {
+ $loc = [$pack,$line];
+ last;
+ }
+ }
+ my sub subwrap { my $sub = shift; sub { tuwf->req->{trace_loc} = $loc; $sub->(@_) } }
+ $f->(map ref($_) eq 'CODE' ? subwrap($_) : $_, @_)
+ }
+ }
+ no warnings 'redefine';
+ my $x = \&TUWF::register; *TUWF::register = wrap($x);# sub { $x->(map ref($_) eq 'CODE' ? wrap($_) : $_, @_) };
+ my $y = \&TUWF::any; *TUWF::any = wrap($y);# sub { $y->(map ref($_) eq 'CODE' ? wrap($_) : $_, @_) };
+}
+
TUWF::load_recursive('VNDB::Util', 'VNDB::DB', 'VNDB::Handler');
TUWF::set import_modules => 0;
TUWF::load_recursive('VNWeb');
+TUWF::hook after => sub {
+ return if rand() > config->{trace_log} || !tuwf->req->{trace_start};
+ my $sqlt = List::Util::sum(map $_->[2], tuwf->{_TUWF}{DB}{queries}->@*);
+ my %elm = map +($_->[0], 1), tuwf->req->{pagevars}{elm}->@*;
+ tuwf->dbExeci('INSERT INTO trace_log', {
+ method => tuwf->reqMethod(),
+ path => tuwf->reqPath(),
+ query => tuwf->reqQuery(),
+ module => tuwf->req->{trace_loc}[0],
+ line => tuwf->req->{trace_loc}[1],
+ sql_num => scalar grep($_->[0] ne 'ping/rollback' && $_->[0] ne 'commit', tuwf->{_TUWF}{DB}{queries}->@*),
+ sql_time => $sqlt,
+ perl_time => time() - tuwf->req->{trace_start},
+ loggedin => auth?1:0,
+ elm_mods => '{'.join(',', sort keys %elm).'}'
+ });
+} if config->{trace_log};
+
TUWF::run if !tuwf->{elmgen};