net/Socket.hpp | 1
scripts/perftrace.pl | 133 +++++++++++++++++++++++++++++++--------------------
2 files changed, 83 insertions(+), 51 deletions(-)
New commits:
commit cacaefc2871b26372ff9aaf3135970dcf2dc2053
Author: Michael Meeks <michael.me...@collabora.com>
AuthorDate: Thu Apr 4 18:55:07 2019 +0100
Commit: Michael Meeks <michael.me...@collabora.com>
CommitDate: Thu Apr 4 19:18:45 2019 +0100
perftrace: Annotate idleness and render it better as gaps.
Change-Id: If4d7853d02ca736f8cab12bd9dcc7c4b60ec7d27
diff --git a/net/Socket.hpp b/net/Socket.hpp
index c2355b7b7..c1c17b2be 100644
--- a/net/Socket.hpp
+++ b/net/Socket.hpp
@@ -488,6 +488,7 @@ public:
int rc;
do
{
+ LOG_TRC("Poll start");
#if !MOBILEAPP
rc = ::poll(&_pollFds[0], size + 1, std::max(timeoutMaxMs,0));
#else
diff --git a/scripts/perftrace.pl b/scripts/perftrace.pl
index 32c0f0a71..a5b1a01d4 100755
--- a/scripts/perftrace.pl
+++ b/scripts/perftrace.pl
@@ -70,21 +70,42 @@ sub offset_microsecs($)
return $usec;
}
-# Delimit spans of time:
-my @pairs = (
+# Important things that happen in pairs
+my @event_pairs = (
+ { type => 'INF',
+ emitter => '^loolwsd$',
+ start => 'Initializing wsd.\.*',
+ end => 'Listening to prisoner connections.*' },
+ { type => 'INF',
+ emitter => '^forkit$',
+ start => 'Initializing frk.\.*',
+ end => 'ForKit process is ready.*' },
{ type => 'INF',
- emitter => 'loolwsd',
- start => 'Initializing wsd.\.*',
- end => 'Listening to prisoner connections.*' },
- { type => 'INF',
- emitter => 'forkit',
- start => 'Initializing frk.\.*',
- end => 'ForKit process is ready.*'
- }
-);
+ emitter => "^lokit_.*",
+ start => 'Loading url .*',
+ end => '^Document loaded in .*ms$' },
+ # FIXME: add save too ...
+ );
+
+# Idle events
+my @idle_types = (
+ '^Poll completed'
+ );
+
my %pair_starts;
my %proc_names;
+sub get_event_type($$$)
+{
+ my ($type, $emitter, $message) = @_;
+ foreach my $match (@idle_types) {
+ if ($message =~ m/$match/) {
+ return 'idle';
+ }
+ }
+ return '';
+}
+
sub consume($$$$$$$$)
{
my ($proc, $pid, $tid, $time, $emitter, $type, $message, $line) = @_;
@@ -108,57 +129,66 @@ sub consume($$$$$$$$)
}
my $handled = 0;
- foreach my $match (@pairs) {
- next if ($type ne $match->{type});
- next if (!($emitter =~ m/$match->{emitter}/));
-
- my $start = $match->{start};
- my $end = $match->{end};
- my $key = $type.$emitter.$start;
- if ($message =~ m/$start/) {
- defined $pair_starts{$key} && die "event $start ($end) starts and
fails to finish";
- $pair_starts{$key} = $time;
- last;
- } elsif ($message =~ m/$end/) {
- defined $pair_starts{$key} || die "event $start ($end) ends but
failed to start";
-
- my $content_e = escape($start);
- my $title_e = escape($line);
- my $start_time = $pair_starts{$key};
- my $end_time = $time;
-
- if ($json)
- {
- my $dur = $end_time - $start_time;
- my $ms = int ($dur / 1000.0);
- push @events, "{\"pid\":$pid, \"tid\":$tid, \"ts\":$start_time,
\"dur\":$dur, \"ph\":\"X\", \"name\":\"$title_e\", \"args\":{ \"ms\":$ms } }";
- }
- else
- {
- my $id = (scalar @events) + 1;
- push @events, "{id: $id, group: $emitters{$emitter}, ".
- "start: new Date('$log_start_date $start_time'), ".
- "end: new Date('$log_start_date $end_time'), ".
- "content: '$content_e', title: '$title_e'}";
- }
- last;
- }
+ foreach my $match (@event_pairs) {
+ next if ($type ne $match->{type});
+ next if (defined $match->{emitter} && !($emitter =~
m/$match->{emitter}/));
+
+ my $start = $match->{start};
+ my $end = $match->{end};
+ my $key = $type.$emitter.$start;
+ if ($message =~ m/$start/) {
+ defined $pair_starts{$key} && die "event $start ($end) starts and
fails to finish";
+ $pair_starts{$key} = $time;
+ last;
+ } elsif ($message =~ m/$end/) {
+ defined $pair_starts{$key} || die "event $start ($end) ends but
failed to start";
+
+ my $content_e = escape($start);
+ my $title_e = escape($line);
+ my $start_time = $pair_starts{$key};
+ my $end_time = $time;
+
+ if ($json)
+ {
+ my $dur = $end_time - $start_time;
+ my $ms = int ($dur / 1000.0);
+ push @events, "{\"pid\":$pid, \"tid\":$tid, \"ts\":$start_time,
\"dur\":$dur, \"ph\":\"X\", \"name\":\"$title_e\", \"args\":{ \"ms\":$ms } }";
+ }
+ else
+ {
+ my $id = (scalar @events) + 1;
+ push @events, "{id: $id, group: $emitters{$emitter}, ".
+ "start: new Date('$log_start_date $start_time'), ".
+ "end: new Date('$log_start_date $end_time'), ".
+ "content: '$content_e', title: '$title_e'}";
+ }
+ last;
+ }
}
my $content_e = escape($message. " " . $line);
if ($json)
{
+ my $event_type = get_event_type($type, $emitter, $message);
+
# join events to the last time
my $dur = 100; # 0.1ms default
my $key = "$pid-$tid";
if (defined($last_times{$key})) {
$dur = $time - $last_times{$key};
my $idx = $last_event_idx{$key};
- $events[$idx] =~ s/\"dur\":100/\"dur\":$dur/;
+
+ if ($event_type ne 'idle') { # onlt re-write if not idle
+ $events[$idx] =~ s/\"dur\":10/\"dur\":$dur/;
+ } else {
+ print STDERR "idle re-write to $dur\n";
+ }
}
$last_times{$key} = $time;
$last_event_idx{$key} = scalar @events;
- push @events, "{\"pid\":$pid, \"tid\":$tid, \"ts\":$time, \"dur\":100,
\"ph\":\"X\", \"s\":\"p\", \"name\":\"$content_e\" }";
+
+ my $json_type = "\"ph\":\"X\", \"s\":\"p\"";
+ push @events, "{\"pid\":$pid, \"tid\":$tid, \"ts\":$time, \"dur\":10,
$json_type, \"name\":\"$content_e\" }";
}
else
{
@@ -252,7 +282,8 @@ if ($input[0] =~ m/^\S+\s([\d-]+)\s+([\d:\.]+)\s+/)
}
# parse all the lines
-while (my $line = shift @input) {
+my $lineno = 0;
+while (my $line = $input[$lineno++]) {
my ($pevent, $pdetail);
$line =~ s/\r*\n*//g;
@@ -263,7 +294,7 @@ while (my $line = shift @input) {
} elsif ($line =~
m/^(\w+)-(\d+)-(\d+)\s+\S+\s+(\S+)\s+\[\s+(\S+)\s+\]\s+(\S+)\s+(.+)$/) { #
split lines ...
my ($proc, $pid, $tid, $time, $emitter, $type, $message, $line) = ($1,
$2, $3, $4, $5, $6, $7);
- while (my $next = shift @input) {
+ while (my $next = $input[$lineno++]) {
# ... | kit/Kit.cpp:1272
if ($next =~ m/^(.*)\|\s+(\S+)$/)
{
@@ -276,7 +307,7 @@ while (my $line = shift @input) {
}
consume($proc, $pid, $tid, $time, $emitter, $type, $message, $line);
} else {
- die "Poorly formed line - is logging.file.flush set to true ?
'$line'\n";
+ die "Poorly formed line on " . ($lineno - 1) . " - is
logging.file.flush set to true ? '$line'\n";
}
}
_______________________________________________
Libreoffice-commits mailing list
libreoffice-comm...@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/libreoffice-commits
