* osstest Massachusetts test lab resource usage investigation
@ 2016-08-25 15:27 Ian Jackson
2016-08-30 10:53 ` [Wg-test-framework] " Ian Jackson
0 siblings, 1 reply; 6+ messages in thread
From: Ian Jackson @ 2016-08-25 15:27 UTC (permalink / raw)
To: xen-devel; +Cc: wg-test-framework
Because I have suspected that we are not getting as much out of the
test lab as we could have, I have been doing some digging in the
database.
I wrote some code to mine the database for historical information
about resource usage. (Patch below, which I will push to osstest
production at some point.)
I ran it on the last 92 days of history (strictly, 92 days starting 7
days ago, because for obscure technical reasons it doesn't want to
look right at the most recent data).
The most noteworthy conclusion I have drawn is that about 30% of the
capacity is not being used. That is, at any one time, on average,
about ~30% of the capacity is idle.
Some of this will be inevitable: for example, if we need to shut the
system down for maintenance, we will need to ask it to drain its queue
so that it is idle by the start of the maintenance window.
It is also possible that some of this is a genuine lack of work to do,
in the sense that the programmed test flights are not able to use the
capacity. I don't think this is very likely (but I haven't yet
figured out for sure). Certainly, my personal impression is that the
lead time on tests has varied greatly; currently it is quite low
because the stable trees haven't had recent updates.
Personal experience and ad-hoc log reading leads me to think that the
biggest likely cause of idle test boxes is database contention. That
is, there is work which the system in some sense knows it ought to be
doing, but it is stuck on bookkeeping operations involved in setting
up a flight, scheduling the jobs, and at the appropriate time
allocating a test box for each such job, and son on. Depending on
locking strategies, these database operations can be blocked by
long-running report jobs. It is also possible that the database
queries involved in host scheduling need tuning.
In parallel with the work I am reporting in this email, I am already
taking steps to investigate the performance of the various database
queries, and the situation with locking.
I hope that this will produce actionable ideas for improvement.
Additionally, each test box spends about ~16% of the time being wiped
and reinstalled for each test. This is because the reinstallation
time is significant when compared to the duration of each test.
It is necessary to reinstall when a host was previously used by a
completely different flight (which might involve a different
hypervisor), or if we aren't sure that the previous test left the host
in a good state. But most flights contain many similar host
installations and most jobs leave the host in a good state.
So there is an opportunity for a worthwhile improvement in throughput
by arranging for test host reuse within a flight.
osstest already understands sharing for the purpose of builds; making
it share for tests, under the right conditions, is a moderately
extensive, but straightforward, task.
About 4% of the capacity is used for builds, but a further 5% or so
preparing a box to be a build host. We could probably optimise this
by providing a few dedicated build hosts, as this would result in
fewer reinstalls. We should consider this in our next round of
provisioning.
(The report also claims that about 3% of the capacity is "unused" when
a machine is configured for building, and osstest would be willing in
principle to run multiple different builds at once, but for scheduling
reasons only one build is running.)
Other interesting results: about 3-4% of the time is spent doing
bisections.
Looking at the branches: the xen-unstable-smoke flights are about 3%.
xen-unstable itself consumes the bulk of the capacity, at about 28%.
qemu-mainline (which updates frequently) is the next biggest.
The graphs are generated using python3-matplotlib and shown on my
workstation's X display. I haven't arranged for them to be output as
PostScript or png or anything - instead I have put a screenshot here:
http://xenbits.xen.org/people/iwj/2016/mg-report-host-usage.2016-08-25.png
I'm afraid that this is likely to be rather opaque unless you look at
the source code (in osstest, and the patch below) to see what the
various categories mean. I also haven't bothered prettifying the
formatting, beyond what's needed to be able to read the charts.
Thanks all for your attention.
Ian.
From 6895c84d890a2db9f68e7994198783c0e4465181 Mon Sep 17 00:00:00 2001
From: Ian Jackson <ian.jackson@eu.citrix.com>
Date: Thu, 25 Aug 2016 15:59:28 +0100
Subject: [OSSTEST PATCH] mg-report-host-usage-*: New admin debugging tools
These two tools can be used to dig into the osstest history and
produce some graphs of what the system is spending its resources on.
Signed-off-by: Ian Jackson <Ian.Jackson@eu.citrix.com>
---
mg-report-host-usage-collect | 443 +++++++++++++++++++++++++++++++++++++++++++
mg-report-host-usage-tuples | 124 ++++++++++++
2 files changed, 567 insertions(+)
create mode 100755 mg-report-host-usage-collect
create mode 100755 mg-report-host-usage-tuples
diff --git a/mg-report-host-usage-collect b/mg-report-host-usage-collect
new file mode 100755
index 0000000..ab43c5f
--- /dev/null
+++ b/mg-report-host-usage-collect
@@ -0,0 +1,443 @@
+#!/usr/bin/perl -w
+
+# This is part of "osstest", an automated testing framework for Xen.
+# Copyright (C) 2009-2016 Citrix Inc.
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program. If not, see <http://www.gnu.org/licenses/>.
+
+
+use strict qw(vars);
+
+use DBI;
+use Osstest;
+use IO::Handle;
+use POSIX;
+use JSON;
+use Data::Dumper;
+use Carp;
+
+$SIG{__WARN__} = sub { confess $_[0]; };
+
+my %hh; # host history
+# contains a list of phases
+# a phase is "this host was used in this way during this period"
+# initially phases may overlap in complex ways
+#
+# $hh{HOST}[]{From} = time_t
+# $hh{HOST}[]{To} = time_t
+# $hh{HOST}[]{KV}{Key} = VALUE
+#
+# Keys are the db results plus (caps are synth ones):
+#
+# PREP = boolish: 1 means was host install or h-build-prep
+# SHAREABLE = boolish: 1 means was sharable during this period
+#
+# Calculated during consolidate:
+# SHARES = 1 or 3 (or 'shared max tasks' host prop)
+# IDLE = 1 or undef
+#
+# Combinations of the above
+# OVERALL IDL
+# TEST-PREP TEST
+# BUILD-PREP BUILD BUILD-IDLE IDLE-PREPPED
+# ^ idle share ^ all shares idle
+#
+# WEIGHT 1.0/SHARES (or 1.0)
+
+our $duration = 31 * 86400;
+our $max_job_len = 86400 * 7;
+our $progress = 1;
+our $debug = 0;
+
+csreadconfig();
+
+open DEBUG, "> /dev/null" or die $!;
+open PROGR, ">& STDERR" or die $!;
+
+while (@ARGV) {
+ $_ = shift @ARGV;
+ last if m/^--?$/;
+ while (m/^-./) {
+ if (s/^-D/-/) {
+ open DEBUG, ">& STDERR" or die $!;
+ open PROGR, "> /dev/null" or die $!;
+ $debug = 1;
+ } elsif (s/^-q/-/) {
+ open PROGR, "> /dev/null" or die $!;
+ } elsif (s/^-l(\d+)([y|m|w|d])$//) {
+ $duration = $1 * ($2 eq 'y' ? 366 :
+ $2 eq 'm' ? 31 :
+ $2 eq 'w' ? 7 :
+ 1) * 86400;
+ } elsif (s/^--max-job-len=(\d+)$//) {
+ $max_job_len = $1;
+ } else {
+ die "$_ ?";
+ }
+ }
+}
+
+PROGR->autoflush(1);
+
+our $cutoff_end = time - $max_job_len;
+our $cutoff_start = $cutoff_end - $duration;
+
+printf STDERR "cutoff start: %s\n", show_abs_time $cutoff_start;
+printf STDERR "cutoff end: %s\n", show_abs_time $cutoff_end;
+
+our $last_progress = 0;
+
+sub progress1 {
+ print DEBUG "@_\n" if $debug;
+ printf PROGR "%-79.79s\r", "@_";
+ $last_progress = time;
+}
+
+sub progress {
+ return unless time > $last_progress;
+ print DEBUG "@_\n" if $debug;
+ local $debug = 0;
+ progress1 @_;
+}
+
+my $propq = db_prepare(<<END);
+ SELECT val
+ FROM resource_properties
+ WHERE restype='host'
+ AND resname=?
+ AND name=?
+END
+
+sub collectdata () {
+ my $startq = db_prepare(<<END);
+ SELECT *
+ FROM flights
+ WHERE flights.started >= ?
+ ORDER BY flight asc
+ LIMIT 1
+END
+ $startq->execute($cutoff_start - $max_job_len);
+ my ($minflight) = $startq->fetchrow_array();
+ die unless defined $minflight;
+
+ progress1 "minflight $minflight";
+
+ my $jobsq = db_prepare(<<END);
+ SELECT flights.flight flight,
+ flights.blessing blessing,
+ flights.branch branch,
+ flights.intended intended,
+ alloc.finished alloc_finished,
+ jobs.job job
+ FROM flights
+ JOIN jobs USING (flight)
+ JOIN steps alloc USING (flight,job)
+ WHERE flights.flight >= ?
+ AND alloc.step='ts-hosts-allocate'
+ AND alloc.status='pass'
+ AND alloc.finished IS NOT NULL
+END
+
+ my $prepq = db_prepare(<<END);
+ SELECT finished prep_finished,
+ status prep_status
+ FROM steps prep
+ WHERE flight=? and job=?
+ AND prep.finished IS NOT NULL
+ AND (prep.step='ts-host-build-prep'
+ OR prep.step like 'ts-host-install%')
+ ORDER BY stepno DESC
+ LIMIT 1
+END
+
+ my $hostsq = db_prepare(<<END);
+ SELECT val, synth
+ FROM runvars
+ WHERE flight=? and job=?
+ AND (name like '%_host' or name='host')
+END
+
+ my $finishq = db_prepare(<<END);
+ SELECT max(finished) AS finished
+ FROM steps
+ WHERE flight=? and job=?
+END
+
+ progress1 "minflight $minflight executing...";
+ $jobsq->execute($minflight);
+
+ progress1 "minflight $minflight fetching...";
+ $last_progress = 0; # forces next progress message to be printed
+
+ while (my $jobrow = $jobsq->fetchrow_hashref()) {
+ my @fj = ($jobrow->{flight}, $jobrow->{job});
+ progress "PROCESSING @fj";
+ my @kvs = (%$jobrow);
+
+ $finishq->execute(@fj);
+ my ($finish) = $finishq->fetchrow_array();
+ die "@fj ?" unless defined $finish;
+
+ $hostsq->execute(@fj);
+ my $hosts = $hostsq->fetchall_arrayref({ });
+
+ my $record_phase = sub {
+ my ($start,$finish,@xkvs) = @_;
+ $finish = $start if $finish < $start; # wtf
+ foreach my $hostrow (@$hosts) {
+ my $hn = $hostrow->{val};
+ print DEBUG " phase $hn $start..$finish @kvs @xkvs\n";
+ push @{ $hh{$hn} }, {
+ From => $start,
+ To => $finish,
+ KV => { @kvs, @xkvs, host_fixed => !$hostrow->{synth} },
+ };
+ }
+ };
+
+ $prepq->execute(@fj);
+ my $preprow = $prepq->fetchrow_hashref();
+ if (defined $preprow) {
+ push @kvs, %$preprow;
+ if ((defined $preprow->{prep_status}) &&
+ $preprow->{prep_status} eq 'pass') {
+ $record_phase->($jobrow->{alloc_finished},
+ $preprow->{prep_finished},
+ 'PREP' => 1,
+ 'SHAREABLE' => 0);
+ $record_phase->($preprow->{prep_finished},
+ $finish,
+ 'PREP' => 0,
+ 'SHAREABLE' => 1);
+ } else {
+ # there was a prep attempt but it didn't pass
+ $record_phase->($jobrow->{alloc_finished},
+ $finish,
+ 'PREP' => 1,
+ 'SHAREABLE' => 0);
+ }
+ } else {
+ # something strange, well, fine
+ $record_phase->($jobrow->{alloc_finished},
+ $finish,
+ PREP => 0,
+ SHAREABLE => 0);
+ }
+ }
+}
+
+sub consolidate_host ($) {
+ my ($hostname) = @_;
+
+ progress1 "host $hostname";
+
+ $propq->execute($hostname, 'shared max tasks');
+ my ($max_shares) = $propq->fetchrow_array();
+ $max_shares ||= 3;
+
+ print DEBUG "host $hostname max_shares=$max_shares\n";
+
+ print DEBUG "host $hostname sorting\n";
+
+ my @sorted = sort { $a->{From} <=> $b->{From} } @{ $hh{$hostname} };
+ my @out;
+ $hh{$hostname} = \@out;
+
+ print DEBUG "host $hostname chopping\n";
+
+ while (@sorted) {
+ my $subphase_start = $sorted[0]{From};
+ my $subphase_end = $sorted[0]{To};
+
+ # We compute the next subphase period, and how many of the
+ # incoming phases overlap with it.
+ #
+ # There are one or more phases which start at $subphase_start.
+ # It is exactly these phases which occur in the subphase.
+ #
+ # The subphase ends when either: one of those subphases ends,
+ # or a subsequent subphase begins
+
+ # We figure out when the next subphase
+
+ my $eat_phases = 0;
+ my $next_event = $subphase_end;
+
+ for (my $i=0; $i<@sorted; $i++) {
+ my $cand_phase = $sorted[$i];
+
+ last if $cand_phase->{From} > $subphase_end;
+ # ... we are well beyond the subphase then
+
+ if ($cand_phase->{From} == $subphase_start) {
+ $eat_phases++;
+ $next_event = $cand_phase->{To};
+ } else {
+ $cand_phase->{From} > $subphase_start or die;
+ $next_event = $cand_phase->{From};
+ }
+ $subphase_end = $next_event if $next_event < $subphase_end;
+ }
+
+ progress sprintf "subphase %-20s %15d %15d %3d",
+ $hostname, $subphase_start, $subphase_end, $eat_phases;
+
+ my @secondhalves;
+ my @subphases;
+ for (my $i=0; $i<$eat_phases; $i++) {
+ my $eating = shift @sorted;
+ die unless $eating->{From} == $subphase_start;
+ die if $eating->{To} < $subphase_end;
+ if ($eating->{To} > $subphase_end) {
+ # Each of the incoming phases which start at the
+ # subphase period and finish after its end is broken
+ # up into two new phases: one which goes into the
+ # output.
+ push @secondhalves, {
+ From => $subphase_end,
+ To => $eating->{To},
+ KV => { %{ $eating->{KV} } },
+ };
+ $eating->{To} = $subphase_end;
+ }
+ push @subphases, $eating;
+ }
+ unshift @sorted, @secondhalves;
+
+ # See if we are sharing, and if so calculate the sharing
+ # fraction and also perhaps invent an idle share. We do this
+ # here so that we are editing in @out. Editing in @sorted
+ # would be wrong because it would affect other subphases.
+
+ my $all_shares = 1;
+ my $max_shares_now = 1;
+ foreach my $sp (@subphases) {
+ $all_shares &&= $sp->{KV}{SHAREABLE};
+ if (defined $sp->{KV}{job} &&
+ $sp->{KV}{job} =~ m/^build/) {
+ $max_shares_now = $max_shares;
+ }
+ }
+ my @sp0kvs = %{ $subphases[0]{KV} };
+
+ if ($all_shares) {
+ if (@subphases > $max_shares_now) {
+ progress1 '';
+ print STDERR "warning: $hostname".
+ " $subphase_start..$subphase_end:".
+ " msn=$max_shares_now != ".(scalar @subphases)."\n";
+ $max_shares_now = @subphases;
+ }
+
+ foreach my $sp (@subphases) {
+ $sp->{KV}{SHARES} = $max_shares_now;
+ }
+
+ while (@subphases < $max_shares_now) {
+ push @subphases, {
+ From => $subphase_start,
+ To => $subphase_end,
+ KV => { @sp0kvs, SHARES => $max_shares_now, IDLE => 1 },
+ };
+ }
+ }
+
+ my $next_phase = $sorted[0];
+ if ($next_phase &&
+ $next_phase->{From} != $subphase_end) {
+ # Need to add an idle phase, to bridge to next incoming
+ # phase.
+ die unless $next_phase->{From} > $subphase_end;
+ push @subphases, {
+ From => $subphase_end,
+ To => $next_phase->{From},
+ KV => $all_shares ? { @sp0kvs, IDLE => 1 } : { IDLE => 1 },
+ };
+ }
+
+ foreach my $sp (@subphases) {
+ my $kv = $sp->{KV};
+ my $jk = (
+ !defined $kv->{job} ? '' :
+ $kv->{job} =~ m/^build/ ? 'BUILD' :
+ 'TEST'
+ );
+ $kv->{OVERALL} =
+ ( $kv->{IDLE} ? ( $kv->{SHARES} ? "IDLE-SHARE-$jk" :
+ $kv->{SHAREABLE} ? "IDLE-PREPPED-$jk" :
+ "IDLE" ) :
+ $kv->{PREP} ? "PREP-$jk" :
+ "$jk"
+ );
+
+ $kv->{WEIGHT} =
+ 1.0 / ( $kv->{SHARES} // 1.0 );
+ }
+
+ foreach my $sp (@subphases) {
+ my @kvs = map { "$_=$sp->{KV}{$_}" } sort keys %{ $sp->{KV} };
+ my $t = $sp->{To} - $sp->{From};
+ printf DEBUG " SP %s %5d %s..%s %skvs\n",
+ $hostname, $t, $sp->{From}, $sp->{To}, "@kvs";
+ $sp->{From} = $cutoff_start if $sp->{From} < $cutoff_start;
+ $sp->{To} = $cutoff_end if $sp->{To} > $cutoff_end;
+ next unless $sp->{From} < $sp->{To};
+ push @out, $sp;
+ }
+ }
+ progress1 '';
+}
+
+sub output_host ($) {
+ my ($hn) = @_;
+
+ my $hostflagsq = db_prepare(<<END);
+ SELECT hostflag f
+ FROM hostflags
+ WHERE hostname = ?
+END
+
+ my %hinfo;
+ $hostflagsq->execute($hn);
+ while (my ($f) = $hostflagsq->fetchrow_array()) {
+ if ($f =~ m/^blessed-real$/) {
+ $hinfo{'HOST_BLESSED_REAL'} = 1;
+ } elsif ($f =~ m/^arch-(?:amd64|i386)$/) {
+ $hinfo{'HOST_ARCH_GROUP'} = 'x86';
+ } elsif ($f =~ m/^arch-arm/) {
+ $hinfo{'HOST_ARCH_GROUP'} = 'arm';
+ }
+ }
+
+ my $hd = $hh{$hn};
+ foreach my $e (@$hd) {
+ my $duration = $e->{To} - $e->{From};
+ my $obj = { %{ $e->{KV} }, %hinfo };
+ delete $obj->{$_} foreach qw(flight alloc_finished prep_finished);
+ $obj->{HOSTNAME} = $hn;
+ $obj->{DURATION} = $duration;
+ $obj->{WDURATION} = $obj->{WEIGHT} * $obj->{DURATION};
+ print encode_json($obj),"\n" or die $!;
+ }
+}
+
+collectdata();
+
+foreach my $h (sort keys %hh) {
+# print DEBUG "\n-------------------- $h --------------------\n";
+# print DEBUG "\n",Dumper($hh{$h});
+ consolidate_host($h);
+# print DEBUG "\n",Dumper($hh{$h});
+ output_host($h);
+}
diff --git a/mg-report-host-usage-tuples b/mg-report-host-usage-tuples
new file mode 100755
index 0000000..375da88
--- /dev/null
+++ b/mg-report-host-usage-tuples
@@ -0,0 +1,124 @@
+#!/usr/bin/python3
+
+import re as regexp
+import sys
+import json
+from collections import defaultdict
+from math import floor, sqrt, ceil
+
+import numpy as np
+import matplotlib.pyplot as plt
+
+kv = defaultdict(lambda: defaultdict(int))
+
+undefstr = '(undef)'
+
+def readin():
+ f = open(sys.argv[1])
+
+ key_bad_re = regexp.compile(r'\W')
+
+ for l in f:
+ obj = json.loads(l)
+ w = obj['DURATION']
+ for k, v in obj.items():
+ assert(not key_bad_re.match(k))
+ assert(len(k))
+ assert(not v==undefstr)
+ if k=='DURATION' or k=='WDURATION': continue
+ kv[k][v] += w
+
+def truncto(totals, maxvlen):
+ ntotals = defaultdict(int)
+ for v, w in totals.items():
+ v = v[0:maxvlen]
+ ntotals[v] += w
+ return ntotals
+
+def makegraph(k, totals):
+ print(k)
+
+ maxvlen = 25
+ maxitems = 30
+
+ while True:
+ totals = truncto(totals, maxvlen)
+
+ if maxvlen <= 1: break
+ if len(totals) <= maxitems: break
+
+ print(" reducing", maxvlen, len(totals))
+ maxvlen -= 1
+
+ vals = totals.keys()
+ vals = sorted(vals)
+ vals.reverse()
+
+ nvals = len(vals)
+ indices = np.arange(nvals)
+ totals = [totals[vals[ix]] for ix in indices]
+
+ total = sum(totals)
+ if total:
+ totals = [x * 100 / total for x in totals]
+
+ #print(str([vals,indices,totals]))
+
+ global subplotnum
+ ax = plt.subplot(subplots_nrows, subplots_ncols, subplotnum)
+ subplotnum += 1
+
+ plt.yticks(indices + 0.35, vals)
+ plt.barh(indices, totals)
+ ax.set_title(k)
+
+akvw = defaultdict(lambda: defaultdict(lambda: defaultdict(float)))
+
+def recordin(obj, w, kvw):
+ for k in kdo:
+ v = obj.get(k,undefstr)
+ kvw[k][str(v)] += w
+
+def readin2():
+ global kdo
+
+ kdo = sorted(kv.keys())
+ #kdo = [ 'branch', 'OVERALL','job' ]
+
+ f = open(sys.argv[1])
+ for l in f:
+ obj = json.loads(l)
+ w = obj['WDURATION']
+ recordin(obj, w, akvw['*'])
+ ag = obj.get('HOST_ARCH_GROUP',undefstr)
+ recordin(obj, w, akvw[ag])
+
+fignum = 0
+
+def basicgraphs(ag, kvw):
+ global fignum
+ global subplotnum
+ global subplots_nrows
+ global subplots_ncols
+
+ fignum = fignum + 1
+ subplotnum = 1
+
+ fig = plt.figure(fignum)
+ titlemsg = ag
+ plt.suptitle(titlemsg)
+ fig.canvas.set_window_title("mg-report-host-usage-tuples " + ag)
+
+ subplots_nrows = floor(sqrt(len(kdo)))
+ subplots_ncols = ceil(len(kdo) / subplots_nrows)
+ for k in kdo:
+ makegraph(k, kvw[k])
+
+def graphs():
+ for ag in sorted(akvw.keys()):
+ basicgraphs(ag, akvw[ag])
+ plt.show()
+
+readin()
+readin2()
+graphs()
--
2.1.4
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel
^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [Wg-test-framework] osstest Massachusetts test lab resource usage investigation
2016-08-25 15:27 osstest Massachusetts test lab resource usage investigation Ian Jackson
@ 2016-08-30 10:53 ` Ian Jackson
2016-09-26 16:42 ` Ian Jackson
` (3 more replies)
0 siblings, 4 replies; 6+ messages in thread
From: Ian Jackson @ 2016-08-30 10:53 UTC (permalink / raw)
To: xen-devel, wg-test-framework
Ian Jackson writes ("[Wg-test-framework] osstest Massachusetts test lab resource usage investigation"):
> In parallel with the work I am reporting in this email, I am already
> taking steps to investigate the performance of the various database
> queries, and the situation with locking.
>
> I hope that this will produce actionable ideas for improvement.
I have now completed the investigation into db queries. The patch for
the code I used is below. The output (for data collected for the past
few days, which I expect to be fairly representative) is here:
http://xenbits.xen.org/people/iwj/2016/mg-db-activity.2016-08-30.txt
Best to download it and view it in less -S. Again, interpreting
these numbers will depend on reading the source code to see what the
various categories mean. I didn't bother with charts because there
are many fewer degrees of freedom here.
The bulk of the delay is caused by connections which have done LOCK
TABLE but are now doing some processing in the client. Originally,
this was necessary because the version of Postgres we were using
didn't support predicate locking; so we would simply lock all the
relevant tables and not rely on database concurrency. But Postgres
9.x does support predicate locking.
Over the past year or so I have done some work to make the code handle
database-condurrency-induced transaction failure. This has been
lightly tested. I think it is probably time now to take out the LOCK
TABLE instructions (and deal with any resulting fallout).
Other notable long-running transactions include:
* The sg-check-tested invocation in cr-daily-branch near line 113
($equivstatusq) which checks whether the baseline revision has been
tested. This could probably be speeded up with an appropriate
index, but it is not particularly critical because it's readonly
and not on a hugely critical path: it runs during flight
construction with no locks held other than the table locks (see
above - these are removeable) and the per-`branch' lock. [1253]
* The `equivalent hosts' query in ts-hosts-allocate-Executive, near
line line 303. I think this query could be optimised. This is a
fairly significant contributor to overall delays, and it runs in a
critical path in the host allocator. It compares unfavourably to
the query which extracts information about the very same host
($recentflights_q in Osstest::Executive::duration_estimator), which
is responsible for a fraction of the query time despite being
having more complex conditions. I think this query may be being
misoptimised and some experimentation would be valuable. [880]
* Next are the three duration estimator / host allocator queries
$recentflights_q, $duration_anyref_q and $duration_duration_q,
which are again on the critical path in the host allocator. These
are necessarily a bit slow because they do quite a bit of
archaeology. Rather than trying to optimise them, it would
probably be worth thinking how to get them off the host allocator
critical path. [196+187+90]
Techniques that come to mind would be memoising the information
(and perhaps updating it with a search of recently completed
flights), or pre-calculating it so that it runs outside the host
allocator job slot (which would, in effect, parallelise the
different jobs' executions of instances of this query).
Getting into the log tail here:
* sg-report-job's query for build jobs (ie, looking for other
jobs to recurse to to calculate the revisions used). [61]
Not worth doing anything about.
* cs-bisection-step's attempt to find a build job to reuse
($reusejob). Maybe some of the indices would help, but this
one isn't critical. [44]
Ian.
From 68e36d6d265e25bae0d4c2c239d11870b856609e Mon Sep 17 00:00:00 2001
From: Ian Jackson <ian.jackson@eu.citrix.com>
Date: Tue, 30 Aug 2016 10:58:50 +0100
Subject: [OSSTEST PATCH] mg-db-activity-*: New admin debugging tools for DB
queries
mg-db-activity-logger can be used to sample the activity in the
database, for consumption by mg-db-activity-redactor.
This can be used to look for long-running db queries and to
investigate lock contention.
Signed-off-by: Ian Jackson <Ian.Jackson@eu.citrix.com>
---
mg-db-activity-logger | 98 +++++++++++++++++++
mg-db-activity-redactor | 245 ++++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 343 insertions(+)
create mode 100755 mg-db-activity-logger
create mode 100755 mg-db-activity-redactor
diff --git a/mg-db-activity-logger b/mg-db-activity-logger
new file mode 100755
index 0000000..c4077a7
--- /dev/null
+++ b/mg-db-activity-logger
@@ -0,0 +1,98 @@
+#!/usr/bin/perl -w
+
+# Needs to be able to connect as the db superuser.
+#
+# So probably has to run as user `postgres'.
+
+use strict;
+use DBI;
+use Data::Dumper;
+
+BEGIN {
+unshift @INC, "$`" if $0 =~ m#/[^/]+$#;
+}
+
+use Osstest;
+
+our $dbname = 'osstestdb';
+our $interval = 60;
+
+while (@ARGV && $ARGV[0] =~ m/^-/) {
+ $_ = shift @ARGV;
+ last if m/^--?$/;
+ while (m/^-./) {
+ if (s/^--db=(.+)$//) {
+ $dbname = $1;
+ } elsif (s/^-t=(\d+)$/-/) {
+ $interval = $1;
+ } else {
+ die "$_ ?";
+ }
+ }
+}
+
+die unless @ARGV == 1;
+our ($outfn) = @ARGV;
+
+our $idbh = DBI->connect("dbi:Pg:dbname=$dbname",'','',
+ { RaiseError => 1, PrintError => 1 });
+
+my @tsfields = qw(backend_start xact_start query_start);
+
+my $iq_tsfields = join ', ', map {
+ "extract(epoch from a.$_) as osstest_${_}";
+} @tsfields;
+
+my $iquery = $idbh->prepare(<<END);
+ SELECT *, $iq_tsfields
+ FROM pg_locks l
+ FULL JOIN pg_stat_activity a
+ ON l.pid = a.procpid
+END
+
+my $odbh = DBI->connect("dbi:SQLite:dbname=$outfn",'','',
+ { RaiseError => 1, PrintError => 1 });
+
+
+my $oquery;
+
+our $mktable_done;
+
+sub mktable () {
+ my $cstmt = "CREATE TABLE IF NOT EXISTS datapoints (\n".
+ " osstest_timestamp INTEGER NOT NULL";
+ my $ostmt = "INSERT INTO datapoints VALUES (?";
+ my $fields = $iquery->{NAME};
+ foreach my $f (@$fields) {
+ $cstmt .= sprintf ",\n %-30s TEXT", $f;
+ $ostmt .= ",?";
+ }
+ $cstmt .= "\n)";
+ $ostmt .= ");";
+ $odbh->do($cstmt);
+ $oquery = $odbh->prepare($ostmt);
+}
+
+for (;;) {
+ $odbh->begin_work;
+
+ my $now = time;
+
+ $iquery->execute();
+ my $dp = $iquery->fetchall_arrayref();
+
+ if (!$mktable_done) {
+ mktable();
+ $mktable_done = 1;
+ }
+
+ foreach my $row (@$dp) {
+ $oquery->execute($now, @$row);
+ }
+
+ $odbh->commit;
+
+ printf "%s: %d rows\n", (show_abs_time $now), (scalar @$dp);
+
+ sleep $interval;
+}
diff --git a/mg-db-activity-redactor b/mg-db-activity-redactor
new file mode 100755
index 0000000..253a976
--- /dev/null
+++ b/mg-db-activity-redactor
@@ -0,0 +1,245 @@
+#!/usr/bin/perl -w
+
+use strict;
+use DBI;
+use Data::Dumper;
+use File::Copy;
+
+BEGIN {
+unshift @INC, "$`" if $0 =~ m#/[^/]+$#;
+}
+
+use Osstest;
+
+our @tsforce;
+
+while (@ARGV && $ARGV[0] =~ m/^-/) {
+ $_ = shift @ARGV;
+ last if m/^--?$/;
+ while (m/^-./) {
+ if (s/^-T(\d+)$/-/) {
+ push @tsforce, $1;
+ } else {
+ die "$_ ?";
+ }
+ }
+}
+
+die unless @ARGV == 2;
+our ($infn,$outfn) = @ARGV;
+
+copy($infn,$outfn);
+
+my $dbh = DBI->connect("dbi:SQLite:dbname=$outfn",'','',
+ { RaiseError => 1, PrintError => 1 });
+
+$dbh->do(<<END);
+ CREATE INDEX
+ IF NOT EXISTS datapoints_ts
+ ON datapoints
+ (
+ osstest_timestamp
+ )
+END
+
+$dbh->do(<<END);
+ ALTER TABLE datapoints
+ ADD COLUMN osstest_waiters
+ INTEGER
+ NOT NULL
+ DEFAULT 0
+END
+
+sub massage_query ($) {
+ local ($_) = @_;
+ $_ //= '<NULL>';
+ s/\$\d+/\$X/g;
+ s/\(val \= \$X(?: OR val \= \$X)*\)/(val =...)/g;
+ s/\b(flight\s*(?:[<>]=?|=)\s*('?))\d+\b\2/$1FFFFF$2/g;
+ s/\b(job\s*=\s*('))[-0-9a-z]+\b\2/$1JJJJJ$2/g;
+ s/\b(stepno\s*=\s*('))\d+\b\2/$1SSSSS$2/g;
+ s/\b(finished\s*(?:[<>]=?|=)\s*('?))\d+\b\2/$1FINISHED$2/g;
+ return $_;
+}
+
+our %total_charge;
+# $total_charge{MANNER}{WHAT}{QUERY} = NUM.DATAPOINTS or SECONDS
+# MANNER is
+# direct cost of each task is accounted to the query it is
+# performing
+# blocker } cost of each task is accounted to the task which
+# mystery } ultimately holds the lock which is blocking it,
+# or maybe to the task whose blocker cannot be found
+# ("mystery" )
+#
+# WHAT is
+#
+# Tasks cost is 1 per task that exists at all
+# Waiters cost is 1 per task that is waiting for a lock
+# Delay cost is for each task the time the current query has
+# been running
+#
+# Sampling means that Tasks and Waiters are linear: they are
+# proportional to the system behaviour. Delay is quadratic, since a
+# long-running query will be billed the duration(s) so far for at each
+# time interval. So Delay is in units of time^2.
+
+sub compute_waiters () {
+ my $tsq = $dbh->prepare(<<END);
+ SELECT DISTINCT
+ osstest_timestamp
+ FROM datapoints
+ ORDER BY osstest_timestamp ASC
+END
+
+ my $eventsq = $dbh->prepare(<<END);
+ SELECT rowid,
+ locktype,
+ database,
+ relation,
+ virtualxid,
+ waiting,
+ granted,
+ procpid,
+ current_query,
+ xact_start,
+ osstest_query_start
+ FROM datapoints
+ WHERE osstest_timestamp = ?
+ ORDER BY procpid,
+ granted DESC,
+ locktype,
+ database,
+ relation,
+ virtualxid
+END
+
+ if (@tsforce) {
+ @tsforce = sort { $a <=> $b } @tsforce;
+ } else {
+ $tsq->execute();
+ }
+
+ our %lastquery;
+
+ while (my ($ts) = (shift @tsforce) // $tsq->fetchrow_array()) {
+ print "#TS=$ts\n";
+ $eventsq->execute($ts);
+ my %pid2info;
+ my %pid2waitlock;
+ my %lockholders;
+ my @waitingpids;
+ while (my $evrow = $eventsq->fetchrow_hashref()) {
+ my $lock = join "#", ($evrow->{locktype} // '',
+ $evrow->{database} // '',
+ $evrow->{relation} // '',
+ $evrow->{virtualxid} // '');
+ my $client = join '#', ($evrow->{procpid} // '',
+ $evrow->{client_addr} // '',
+ $evrow->{client_hostname} // '',
+ $evrow->{client_port} // '');
+ my $pid = $evrow->{procpid};
+ my $cqd = $evrow->{current_query} // '<NONE>';
+ $cqd =~ s/\s+/ /g;
+ $cqd =~ s/^\s+//;
+ $cqd =~ s/\s+$//;
+ #print "#TS=$ts pid=".($pid//'none')." LQ=| ".
+ # ($lastquery{$client} // '<UNDEF>')."\n";
+ $lastquery{$client} //= ['<UNKNOWN>'];
+ my @cqd = @{ $lastquery{$client} };
+ push @cqd, $cqd unless @cqd && $cqd[$#cqd] eq $cqd;
+ if ($cqd =~ m#^\<IDLE\>#) {
+ #
+ } elsif ($cqd =~ m#^LOCK TABLE\b#i) {
+ $lastquery{$client} = \@cqd;
+ } else {
+ @cqd = ($cqd[$#cqd]);
+ $lastquery{$client} = \@cqd;
+ }
+ $cqd = join ' | ', @cqd;
+ #print "#TS=$ts pid=".($pid//'none')." LQ=| $lastquery{$client}\n";
+ $evrow->{QUERY} = $cqd;
+ print "#TS=$ts pid=".($pid//'none')." lock=$lock".
+ " granted=".!!$evrow->{granted}.
+ " waiting=".!!$evrow->{waiting}." | $cqd\n";
+ $pid2info{$pid} = $evrow if defined $pid;
+ if ($evrow->{granted}) {
+ push @{ $lockholders{$lock} }, $pid;
+ next;
+ } elsif ($evrow->{waiting}) {
+ die unless defined $pid;
+ die if $pid2waitlock{$pid};
+ $pid2waitlock{$pid} = $lock;
+ }
+ }
+ foreach my $pid (sort keys %pid2info) {
+ my $evrow = $pid2info{$pid};
+ if (!defined $evrow->{xact_start}) {
+ print "#%S=$ts pid=$pid no charge\n";
+ next;
+ }
+ my %tcost = (
+ Tasks => 1,
+ Waiters => !!$evrow->{waiting},
+ Delay => (defined $evrow->{osstest_query_start} ?
+ ($ts - $evrow->{osstest_query_start}) : 0),
+ );
+
+ my $query = massage_query $evrow->{QUERY};
+ print "#TS=$ts pid=$pid costs=".
+ (join ' ', map { "$_=$tcost{$_}" } sort keys %tcost).
+ " QS=$evrow->{xact_start} QUERY=$query\n";
+
+ my $charge_someone = sub {
+ my ($chargepid, $factor, $manner) = @_;
+ print "#%S=$ts pid=$pid charge=$chargepid $factor $manner\n";
+ foreach my $tcostk (keys %tcost) {
+ $total_charge{$manner}{$tcostk}{$query} +=
+ $tcost{$tcostk} * $factor;
+ }
+ };
+
+ my $charge_blocker;
+ $charge_blocker = sub {
+ my ($chargepid, $factor) = @_;
+ my $lock = $pid2waitlock{$chargepid};
+
+ print "#%S=$ts pid=$pid charge_blocker".
+ " pid=$chargepid factor=$factor".
+ " lock=".($lock//'<undef>')."\n";
+ if (!defined $lock) {
+ $charge_someone->($chargepid, $factor, 'blocker');
+ return;
+ }
+ my $holders = $lockholders{$lock};
+ if (!@$holders) {
+ $charge_someone->($chargepid, $factor, 'mystery');
+ return;
+ }
+ foreach my $h (@$holders) {
+ $charge_blocker->($h, $factor * 1.0 / @$holders);
+ }
+ };
+
+ $charge_someone->($pid, 1.0, 'direct');
+ $charge_blocker->($pid, 1.0);
+ }
+ }
+}
+
+sub printout () {
+ foreach my $manner (sort keys %total_charge) {
+ my $imanner = $total_charge{$manner};
+ foreach my $what (sort keys %$imanner) {
+ my $iwhat = $imanner->{$what};
+ foreach my $query (sort { $iwhat->{$b} <=> $iwhat->{$a} }
+ keys %$iwhat) {
+ printf "%-7s %-7s | %10d %s\n", $manner, $what,
+ $iwhat->{$query}, $query;
+ }
+ }
+ }
+}
+
+compute_waiters();
+printout();
--
2.1.4
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel
^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [Wg-test-framework] osstest Massachusetts test lab resource usage investigation
2016-08-30 10:53 ` [Wg-test-framework] " Ian Jackson
@ 2016-09-26 16:42 ` Ian Jackson
2016-09-26 16:42 ` [OSSTEST PATCH 1/3] Add *.tmp to .gitignore Ian Jackson
` (2 subsequent siblings)
3 siblings, 0 replies; 6+ messages in thread
From: Ian Jackson @ 2016-09-26 16:42 UTC (permalink / raw)
To: xen-devel, wg-test-framework
Ian Jackson writes ("Re: [Wg-test-framework] osstest Massachusetts test lab resource usage investigation"):
> I have now completed the investigation into db queries.
I've been looking at the bisector too. I captured a history snapshot
containing two bisections chosen arbitrarily, and wrote some scripts
which I used to analyse the snapshot.
Xen 4.5 build failure around 20th of September.
The bisector completed bisections of both the amd64 and i386 build
failures, in that order. Here is the top time spent for amd64:
68.69% 41208 flight - step start build hosts-allocate | flight - step finish build
10.96% 6577 flight - step start build host-install(3) | flight - step finish build
10.53% 6316 flight - step start build .*-build | flight - step finish build
5.42% 3249 flight - step start build host-(?:install|build-prep) | flight - step finish build
0.76% 453 email - testing | flight - job start
And for i386:
49.22% 8976 flight - step start build hosts-allocate | flight - step finish build
19.51% 3557 flight - step start build .*-build | flight - step finish build
13.10% 2389 flight - step start build host-install(3) | flight - step finish build
5.49% 1002 flight - step start build host-(?:install|build-prep) | flight - step finish build
2.24% 409 flight - flight ending | mtime - transcript
Overall it spent 50-70% of the elapsed time waiting for a slot on a
build machine, and then 16-20% of the elapsed time reinstalling the
build machine.
I think this could be improved by providing one or more hosts which
were dedicated to building. They would not need reinstalling so
often, and would often be idle.
Looking at the logs there is a particularly long delay (15ks, 4h12)
before the first repro job completes. I think this is probably
because each bisection job runs with the start time priority of the
first one, so that the first job is delayed by (roughly) the queue
length. This is done deliberately to avoid trying to bisect things
which are fixed quickly. Given the small proportion of our resources
being used for bisections we may want to reconsider that.
Xen 4.5 guest migration failure around 22nd September.
(test-amd64-amd64-xl-qemuu-winxpsp3, step guest-localmigrate/x10.
The bisector ran first for a different failure,
test-amd64-amd64-xl-qemuu-ovmf-amd64 and determined that that one was
unreproducible.
I have analysed data only up to Thu, 22 Sep 2016 07:59:02 GMT (since
that was in my collection snapshot).
Counting the whole period from the failure of the main flight to the
end of the snapshot recording, we have the following elapsed times:
35.05% 23613 flight - step start build hosts-allocate | flight - step finish build
18.85% 12698 flight - step start test hosts-allocate | flight - step finish test
14.79% 9965 flight - step start test windows-install | flight - step finish test
These figures will disproportionately bias the initial startup host
allocation delay (see above), since this is not a finished bisection.
Counting only the period after the ovmf bisection was abandoned,
37.11% 9965 flight - step start test windows-install | flight - step finish test
10.97% 2946 flight - step start test hosts-allocate | flight - step finish test
8.13% 2183 flight - step start test host-install(3) | flight - step finish test
7.05% 1892 flight - step start test (?!capture|host-install|hosts-allocate|windows-install).* | flight - step finish test
6.32% 1697 flight - step start build .*-build | flight - step finish build
6.15% 1650 flight - step start build host-install(3) | flight - step finish build
5.47% 1470 mtime - bisection-report | mtime - transcript
4.54% 1220 crlog - begin | email - testing
3.42% 918 flight - step start build host-(?:install|build-prep) | flight - step finish build
1.75% 470 flight - job finish | flight - step finish build
Looking at the logs each iteration takes about 1 hour.
This bisection involves a much longer iteration for each step, because
the test involves a Windows install. So the host allocation delay
here is a much smaller proportion, even though the bisector needs to
get exactly the right host.
11% is not that much here, but a faster test would make this look
worse. I have a half-baked idea to allow an in-progress bisection to
reserve its test host. I think that this would be worth pursuing,
although there's a fair amount of complication involved.
38% of the wall clock time was spent doing a Windows install. The
test does a fresh install each time, rather than saving a VM image and
reusing it.
In principle it might be possible to use saved VM images. We do fresh
installs because installs are a good exercise of a variety of
functionality, and because that avoids having to maintain and
comprehend a library of VMs. In particular: if we were maintaining a
library of VMs they would have to be updated occasionally (when), and
problems which arose due to changes in the VM library would be
obscure. I don't think changes in this area are particularly easy.
Windows installs are a pathological case because they are so slow.
Most guest installs done by osstest are much faster. And when there
seem to be multiple regressions, osstest choses to work first on the
one whose test is shortest - hence picking an Debian install on OVMF
first, here.
About 15% of the time (depending how you count it) seems to be going
on bookkeeping of one kind or another, including the archaelogy
necessary to decide what the next revision to test is. In a faster
test this would be quite a large proportion of the elapsed time. My
other reports, particularly the one one on database transaction
performance, contain some suggestions on how this might be improved.
In general I think the database concurrency issues I discussed in my
email
Subject: Re: [Wg-test-framework] osstest Massachusetts test lab resource usage investigation
Date: Tue, 30 Aug 2016 11:53:18 +0100
will help with this.
I expect many developers will think that osstest's bisector is
spending far too much time on setup, during each bisection iteration.
It's always wiping a host, reinstalling with the relevant Xen, and
(if the failure is not before then) reinstalling the guest OS.
But of course a human is likely to be able to tell whether a
particular issue could have been the result of (for example)
corruption which occurred during the install phase. It's also
possible for bugs to even cause disk corruption on the host.
To avoid giving wrong answers it seems best to me for the osstest
bisector to use a strategy which is somewhat slower but which is sure
not to be misled.
I will send my scripts as a followup to this email.
Ian.
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel
^ permalink raw reply [flat|nested] 6+ messages in thread
* [OSSTEST PATCH 1/3] Add *.tmp to .gitignore
2016-08-30 10:53 ` [Wg-test-framework] " Ian Jackson
2016-09-26 16:42 ` Ian Jackson
@ 2016-09-26 16:42 ` Ian Jackson
2016-09-26 16:42 ` [OSSTEST PATCH 2/3] mg-bisect-activity-*: New rather ad-hoc scripts for wall clock timing analysys Ian Jackson
2016-09-26 16:42 ` [OSSTEST PATCH 3/3] mg-bisect-activity-dump-periods: Split out windows-install steps Ian Jackson
3 siblings, 0 replies; 6+ messages in thread
From: Ian Jackson @ 2016-09-26 16:42 UTC (permalink / raw)
To: xen-devel; +Cc: Ian Jackson
Signed-off-by: Ian Jackson <Ian.Jackson@eu.citrix.com>
---
.gitignore | 1 +
1 file changed, 1 insertion(+)
diff --git a/.gitignore b/.gitignore
index bccf488..69f7743 100644
--- a/.gitignore
+++ b/.gitignore
@@ -1,6 +1,7 @@
*~
*.bak
tmp
+*.tmp
bisection.ps
bisection.dot
bisection.html
--
2.1.4
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel
^ permalink raw reply related [flat|nested] 6+ messages in thread
* [OSSTEST PATCH 2/3] mg-bisect-activity-*: New rather ad-hoc scripts for wall clock timing analysys
2016-08-30 10:53 ` [Wg-test-framework] " Ian Jackson
2016-09-26 16:42 ` Ian Jackson
2016-09-26 16:42 ` [OSSTEST PATCH 1/3] Add *.tmp to .gitignore Ian Jackson
@ 2016-09-26 16:42 ` Ian Jackson
2016-09-26 16:42 ` [OSSTEST PATCH 3/3] mg-bisect-activity-dump-periods: Split out windows-install steps Ian Jackson
3 siblings, 0 replies; 6+ messages in thread
From: Ian Jackson @ 2016-09-26 16:42 UTC (permalink / raw)
To: xen-devel; +Cc: Ian Jackson
Signed-off-by: Ian Jackson <ian.jackson@eu.citrix.com>
---
.gitignore | 2 +
README.bisect-wallclock-analysis | 85 ++++++++++++++++++
mg-bisect-activity-collect-emails | 55 ++++++++++++
mg-bisect-activity-collect-tmpdir | 94 ++++++++++++++++++++
mg-bisect-activity-create-db | 17 ++++
mg-bisect-activity-dump-periods | 181 ++++++++++++++++++++++++++++++++++++++
6 files changed, 434 insertions(+)
create mode 100644 README.bisect-wallclock-analysis
create mode 100755 mg-bisect-activity-collect-emails
create mode 100755 mg-bisect-activity-collect-tmpdir
create mode 100755 mg-bisect-activity-create-db
create mode 100755 mg-bisect-activity-dump-periods
diff --git a/.gitignore b/.gitignore
index 69f7743..425506b 100644
--- a/.gitignore
+++ b/.gitignore
@@ -33,3 +33,5 @@ images
diskusage-[A-Z]*.html
diskusage-[A-Z]*.png
diskusage-[A-Z]*.pdf
+bisect-timing.db
+*.tmp
diff --git a/README.bisect-wallclock-analysis b/README.bisect-wallclock-analysis
new file mode 100644
index 0000000..856ee2c
--- /dev/null
+++ b/README.bisect-wallclock-analysis
@@ -0,0 +1,85 @@
+General approach
+----------------
+
+ * Decide what branch to analyise.
+
+ * Save all the relevant emails generated by osstest (including the
+ main flight reports and the bisection reports) to an mbox called
+ eg bisect-data/report-emails
+
+ * Make a copy (with timestamps!) the tmp/ directory of the relevant
+ tree on the controller, eg in bisect-data/tmp with something like
+ rsync -aH osstest.test-lab:/home/osstest/bisects/for-xen-4.5-testing.git/tmp bisect-data/.
+
+ * Run
+ ./mg-bisect-activity-create-db
+ ./mg-bisect-activity-collect-emails <bisect-data/report-emails
+ ./mg-bisect-activity-collect-tmpdir bisect-data/tmp
+ This will result in a sqlite3 datbase called bisect-timing.db
+
+ * Run ./mg-bisect-activity-dump-periods
+ and deal with any complaints "missing" and "cyclic" (see below).
+
+ * Decide what bisection to look at and find in the saved mbox:
+ A The main report flight
+ B The last subsequent email relating to any previous bisection
+ attempt on the same branch (ie of a different job)
+ C The final bisection email for the bisection of interest6
+
+ Convert the Date: headers to time_ts with
+ TZ=UTC date +%s -d 'Tue, 20 Sep 2016 00:13:21 GMT'
+ or whatever.
+
+ Then run some or all of
+ ./mg-bisect-activity-dump-periods A B
+ ./mg-bisect-activity-dump-periods B C
+ ./mg-bisect-activity-dump-periods A C
+ as you like. (If there is no C, leave it off.)
+
+
+Event ordering
+--------------
+
+mg-bisect-activity-dump-periods produces a report which identifies
+"periods" in the data, classifies those "periods", and adds up the
+elapsed time for each class.
+
+A period is the time between two events. An event is something
+evident from the mbox or the tmp/ directory. Events are shown by
+mg-bisect-activity-dump-periods as "some - series - of - words".
+
+They do not contain " | ": this is used as a separtor.
+
+The raw data collection is done only to second resolution, so often
+the data contains events which are "simultaneous".
+
+For events A and B both occurring at timestamp T
+mg-bisect-activity-dump-periods looks at the data to see if it can
+figure out what order those events (A and B) "usually" come in.
+
+It will report "missing" for two events if that can't be determined.
+It will report "cyclic" if the data seems to suggest a cycle (ie two
+or more events on which relation "data suggests P occurs before Q"
+forms a cyclic graph).
+
+In each case the answer is to add to the __DATA__ section of
+mg-bisect-activity-dump-periods a line specifying "X | Y" where X is
+an event which you would expect (from your knowledge of the system)
+would generally precede Y. This will be used both to remove incorrect
+edges (sorting out cycles) and to add missing edges.
+
+If there is a whole category of such, consider whether to do something
+programmating (like "m/^flight - step start ..." which is there
+already).
+
+
+Period squashing
+----------------
+
+The final part of __DATA_ is a list of regexps which are to match
+periods. They are to match on
+
+ event | event
+
+and whenever one matches, the matching period is replaced by the text
+of the regexp. This allows boringly-similar periods to be aggregated.
diff --git a/mg-bisect-activity-collect-emails b/mg-bisect-activity-collect-emails
new file mode 100755
index 0000000..e459aa8
--- /dev/null
+++ b/mg-bisect-activity-collect-emails
@@ -0,0 +1,55 @@
+#!/bin/bash
+
+set -e
+set -o pipefail
+set -o posix
+
+# usage: ./mg-bisect-activity-collect-emails <MBOX 'FROMPATTERN'
+
+OSSTEST_BACEF="$1" formail -c -s perl -we '
+ use strict;
+ our %h;
+ while (<>) {
+ chomp;
+ last if m/^$/;
+ if (m/^([^:]+)\:\s/) {
+ $h{lc $1} = $'\'';
+ }
+ }
+ while (<>) { }
+ die unless $h{subject};
+ my $date = $h{"x-original-date"} || $h{date};
+ die unless $date;
+ exit 0 unless $h{from} =~ m/$ENV{OSSTEST_BACEF}/o;
+ $_ = $h{subject} ;
+ s/\s+/ /g;
+ if (m/^\[[^][]+ bisection\](?: \d+\:)? (\w+) /) {
+ print "$1";
+ } elsif (m/^\[[^][ ]+ test\] \d+\: /) {
+ print "MAINREPORT";
+ } else {
+ chomp;
+ warn "$_\n";
+ exit 0;
+ }
+ print "\t";
+ flush STDOUT or die $!;
+ system(qw(date -d), $date, "+\%s") and die "$? $!";
+' | perl -we '
+ use strict;
+ use DBI;
+ #use Data::Dumper;
+ my $dbh = DBI->connect("dbi:SQLite:dbname=bisect-timing.db","","",
+ { RaiseError => 1, PrintError => 1 });
+ $dbh->begin_work();
+ my $stmt = $dbh->prepare(
+ "INSERT INTO events (evt,ts,cat) VALUES (?,?,'\''email'\'')"
+ );
+ while (<>) {
+ chomp or die;
+ my @v = split /\t/;
+ #print Dumper($_, \@v);
+ $stmt->execute(@v);
+ }
+ $dbh->commit();
+'
diff --git a/mg-bisect-activity-collect-tmpdir b/mg-bisect-activity-collect-tmpdir
new file mode 100755
index 0000000..1ba92bc
--- /dev/null
+++ b/mg-bisect-activity-collect-tmpdir
@@ -0,0 +1,94 @@
+#!/usr/bin/perl -w
+#
+# usage: ./mg-bisect-activity-collect-tmpdir PATH/TO/tmp
+
+use strict;
+use DBI;
+
+my $dbh = DBI->connect("dbi:SQLite:dbname=bisect-timing.db","","",
+ { RaiseError => 1, PrintError => 1 });
+
+$dbh->begin_work();
+
+my $stmt = $dbh->prepare("INSERT INTO events (ts,cat,evt) VALUES (?,?,?)");
+
+my ($inputdir) = @ARGV;
+
+sub date2ts ($) {
+ my ($date) = @_;
+ open S, "-|", qw(date -d), $date, qw(+%s) or die $!;
+ my $ts = <S>;
+ close S;
+ chomp $ts or die "$? $!";
+ $ts;
+}
+
+foreach my $f (<$inputdir/*>) {
+ $_ = $f; s#.*/##;
+
+ my $mtime = sub {
+ my ($evt,$cat) = @_;
+
+ lstat $f or die $!;
+ die unless -f _;
+ my $ts = ((stat _)[9]);
+
+ $stmt->execute($ts, ($cat // 'mtime'), $evt);
+ };
+
+ my @ec;
+ if (m/^t\./) {
+ } elsif (m/^\d+\.
+ ( transcript
+ | bisection-summary
+ | bisection-report
+ | email\.sent
+ )$/x) {
+ $mtime->($1);
+ } elsif (m/^bisection-start-stamp$/) {
+ $mtime->($&, 'unique');
+ } elsif (m/^bisection-start-stamp\.new$/) {
+ } elsif (m/^cr-for-branches.log[-.0-9a-z]*$/) {
+ if (m/\.gz$/) {
+ open L, "zcat $f |" or die $!;
+ } else {
+ open L, "<", $f or die $!;
+ }
+ my $flightfirst;
+ while (<L>) {
+ if (m/^\[(\d\d\d\d\-\d\d\-\d\d \d\d:\d\d:\d\d UTC) \d+\] /) {
+ my $ts = date2ts($1);
+ if (m/\.\.\.$/) {
+ $stmt->execute($ts, 'crlog', 'begin');
+ } elsif (m/ status=\d+\s*$/) {
+ $stmt->execute($ts, 'crlog', 'end');
+ } else {
+ $stmt->execute($ts, 'crlog', 'unknown');
+ }
+ } elsif (m/^export OSSTEST_RESOURCE_WAITSTART=(\d+)$/) {
+ $stmt->execute($1, 'waitstart', 'export');
+ } elsif (s/^(\d\d\d\d\-\d\d\-\d\d \d\d:\d\d:\d\d Z )//) {
+ my $ts = date2ts($1);
+ if (m/^flight \d+ / && !($flightfirst++)) {
+ $stmt->execute($ts, 'flight', 'flight start');
+ } elsif (m/^flight \d+ spawning/) {
+ $stmt->execute($ts, 'flight','job start');
+ } elsif (m/^flight \d+ reaped/) {
+ $stmt->execute($ts, 'flight','job finish');
+ } elsif (m/^flight \d+ (ended|ending) finished\.$/) {
+ $stmt->execute($ts, 'flight',"flight $1");
+ } elsif (m/^\[(\w+)[^][]+\] starting .* (\S+)$/) {
+ $stmt->execute($ts, 'flight', "step start $1 $2");
+ } elsif (m/^\[(\w+)[^][]+\] finished/) {
+ $stmt->execute($ts, 'flight', "step finish $1");
+ }
+ }
+ }
+ } elsif (m/^bisected\./) {
+ $mtime->('bisected');
+ } else {
+ warn $f;
+ }
+}
+
+$dbh->commit();
diff --git a/mg-bisect-activity-create-db b/mg-bisect-activity-create-db
new file mode 100755
index 0000000..7e54f52
--- /dev/null
+++ b/mg-bisect-activity-create-db
@@ -0,0 +1,17 @@
+#!/bin/bash
+set -e
+set -o pipefail
+set -o posix
+
+# usage: ./mg-bisect-activity-create-db
+# overwrites bisect-timing.db unconditionally
+
+rm -f bisect-timing.db
+sqlite3 bisect-timing.db -batch </dev/null -cmd '
+ CREATE TABLE events (
+ ts INTEGER NOT NULL,
+ cat TEXT NOT NULL,
+ evt TEXT NOT NULL
+ );
+ CREATE INDEX events_ts_ix ON events (ts);
+'
diff --git a/mg-bisect-activity-dump-periods b/mg-bisect-activity-dump-periods
new file mode 100755
index 0000000..0c04720
--- /dev/null
+++ b/mg-bisect-activity-dump-periods
@@ -0,0 +1,181 @@
+#!/usr/bin/perl -w
+#
+# usage: ./mg-bisect-activity-collect-tmpdir PATH/TO/tmp
+
+use strict;
+use DBI;
+use Data::Dumper;
+use Graph::Directed;
+
+my ($begin,$end) = @ARGV;
+
+my $dbh = DBI->connect("dbi:SQLite:dbname=bisect-timing.db","","",
+ { RaiseError => 1, PrintError => 1, ReadOnly => 1 });
+
+$dbh->begin_work();
+
+my $exclude_cond = <<END;
+ (
+ (cat = 'email' AND evt = 'MAINREPORT')
+ OR (cat = 'unique')
+ )
+END
+
+my $time_cond = '1=1';
+$time_cond .= " AND ts >= $begin" if defined $begin;
+$time_cond .= " AND ts <= $end" if defined $end;
+$time_cond = "($time_cond)";
+
+my $tq = $dbh->prepare(<<END);
+ SELECT DISTINCT ts
+ FROM events
+ WHERE NOT $exclude_cond
+ AND $time_cond
+ ORDER BY ts ASC
+END
+
+my $eq = $dbh->prepare(<<END);
+ SELECT DISTINCT (cat || ' - ' || evt)
+ FROM events
+ WHERE ts = ?
+ AND NOT $exclude_cond
+ ORDER BY cat, evt
+END
+
+our %evts;
+our %thisorder;
+
+sub getevts ($) {
+ my ($ts) = @_;
+ $eq->execute($ts);
+ return map { $_->[0] } @{ $eq->fetchall_arrayref() };
+}
+
+sub evlk ($) { join ' | ', @{$_[0]} };
+
+$tq->execute();
+my $lastevts;
+while (my ($ts) = $tq->fetchrow_array()) {
+ my @evts = getevts($ts);
+
+ $evts{$_}++ foreach @evts;
+
+ if ($lastevts) {
+ if (@evts==1 && @$lastevts==1) {
+ my @k = (@$lastevts, @evts);
+ $thisorder{join "\t", @k}++;
+ }
+ }
+ $lastevts = \@evts;
+}
+
+sub forceorder ($$) {
+ my ($e,$f) = @_;
+ $thisorder{ join "\t", $e, $f }++;
+ delete $thisorder{ join "\t", $f, $e };
+}
+
+while (<DATA>) {
+ s/\s+$//;
+ next unless m/\S/;
+ last if m/^-/;
+ m/ \| / or die "$_ ?";
+ forceorder($`, $');
+}
+
+foreach (sort keys %evts) {
+ if (m/^flight - step start (\w+) /) {
+ forceorder($_, "flight - step finish $1");
+ }
+}
+
+our @squashes;
+
+while (<DATA>) {
+ s/\s+$//;
+ next unless m/\S/;
+ push @squashes, $_;
+}
+
+#print Dumper(\%thisorder);
+our %periods;
+
+$tq->execute();
+my $lastevt;
+my $lastts;
+while (my ($ts) = $tq->fetchrow_array()) {
+ my @evts = getevts($ts);
+ if (@evts > 1) {
+ my $g = new Graph::Directed;
+ foreach my $e (@evts) {
+ $g->add_vertex($e);
+ foreach my $f (@evts) {
+ next if $e eq $f;
+ next unless $thisorder{ join "\t", $e, $f };
+ $g->add_edge($e, $f);
+ }
+ }
+ if ($g->is_cyclic) {
+ my @cycle = $g->find_a_cycle;
+ die "$ts cyclic ".(join " | ", @cycle);
+ }
+ $g = $g->transitive_closure;
+ my $exp_edges = (@evts/2 * (@evts-1));
+ if ($g->edges != $exp_edges) {
+ foreach my $e (@evts) {
+ foreach my $f (@evts) {
+ next if $e eq $f;
+ next if $g->has_edge($e,$f);
+ next if $g->has_edge($f,$e);
+ die "$ts missing $e | $f";
+ }
+ }
+ die "$ts ".Dumper(\@evts, $g)." ?" if $@;
+ }
+ @evts = sort { $g->has_edge($a,$b) ? +1 : -1 } @evts;
+ }
+ foreach my $evt (@evts) {
+ $evt =~ s/^$_$/$_/ foreach (@squashes);
+ if (defined $lastevt) {
+ $periods{"$lastevt | $evt"} += ($ts - $lastts);
+ }
+ $lastevt = $evt;
+ $lastts = $ts;
+ }
+}
+
+my $total = 0;
+$total += $_ foreach values %periods;
+
+sub prperiod () {
+ printf "%5.2f%% %10d %s\n", 100.0*$periods{$_}/$total, $periods{$_}, $_;
+}
+
+prperiod() foreach sort keys %periods;
+
+print "\n";
+
+prperiod() foreach sort { $periods{$b} <=> $periods{$a} } keys %periods;
+
+$dbh->rollback();
+
+# Two lots of stuff:
+# - orderings of possibly-simultaenous events
+# (see README.bisect-wallclock-analysis)
+# - regexps for squashing periods; each entry in the list
+# replaces all matching periods with a copy of the regexp
+__DATA__
+email - tested | email - testing
+mtime - email.sent | email - testing
+mtime - bisection-summary | mtime - bisection-report
+flight - flight ended | mtime - transcript
+flight - step finish build | flight - job finish
+flight - flight start | flight - job start
+mtime - bisection-report | mtime - bisected
+email - unreproducible | crlog - end
+email - complete | crlog - end
+--
+flight - step start build host-(?:install|build-prep)
+flight - step start build .*-build
+flight - step start test capture-logs.*
+flight - step start test (?!capture|host-install|hosts-allocate).*
--
2.1.4
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel
^ permalink raw reply related [flat|nested] 6+ messages in thread
* [OSSTEST PATCH 3/3] mg-bisect-activity-dump-periods: Split out windows-install steps
2016-08-30 10:53 ` [Wg-test-framework] " Ian Jackson
` (2 preceding siblings ...)
2016-09-26 16:42 ` [OSSTEST PATCH 2/3] mg-bisect-activity-*: New rather ad-hoc scripts for wall clock timing analysys Ian Jackson
@ 2016-09-26 16:42 ` Ian Jackson
3 siblings, 0 replies; 6+ messages in thread
From: Ian Jackson @ 2016-09-26 16:42 UTC (permalink / raw)
To: xen-devel; +Cc: Ian Jackson
Signed-off-by: Ian Jackson <Ian.Jackson@eu.citrix.com>
---
mg-bisect-activity-dump-periods | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/mg-bisect-activity-dump-periods b/mg-bisect-activity-dump-periods
index 0c04720..00576a0 100755
--- a/mg-bisect-activity-dump-periods
+++ b/mg-bisect-activity-dump-periods
@@ -178,4 +178,4 @@ email - complete | crlog - end
flight - step start build host-(?:install|build-prep)
flight - step start build .*-build
flight - step start test capture-logs.*
-flight - step start test (?!capture|host-install|hosts-allocate).*
+flight - step start test (?!capture|host-install|hosts-allocate|windows-install).*
--
2.1.4
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel
^ permalink raw reply related [flat|nested] 6+ messages in thread
end of thread, other threads:[~2016-09-26 16:42 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-08-25 15:27 osstest Massachusetts test lab resource usage investigation Ian Jackson
2016-08-30 10:53 ` [Wg-test-framework] " Ian Jackson
2016-09-26 16:42 ` Ian Jackson
2016-09-26 16:42 ` [OSSTEST PATCH 1/3] Add *.tmp to .gitignore Ian Jackson
2016-09-26 16:42 ` [OSSTEST PATCH 2/3] mg-bisect-activity-*: New rather ad-hoc scripts for wall clock timing analysys Ian Jackson
2016-09-26 16:42 ` [OSSTEST PATCH 3/3] mg-bisect-activity-dump-periods: Split out windows-install steps Ian Jackson
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).