[Libreoffice-commits] online.git: Branch 'distro/collabora/collabora-online-4' - 2 commits - kit/Kit.cpp scripts/perftrace.pl
Libreoffice Gerrit user
logerrit at kemper.freedesktop.org
Wed Apr 24 12:39:16 UTC 2019
kit/Kit.cpp | 2
scripts/perftrace.pl | 108 +++++++++++++++++++++++++++++++++------------------
2 files changed, 73 insertions(+), 37 deletions(-)
New commits:
commit 977aed538437f391dcc3c7fb5521eb0decd6dc3b
Author: Michael Meeks <michael.meeks at collabora.com>
AuthorDate: Fri Apr 5 17:51:02 2019 +0100
Commit: Ashod Nakashian <ashnakash at gmail.com>
CommitDate: Wed Apr 24 14:39:08 2019 +0200
perftrace: trace more pairs and output line number details too.
Change-Id: I48c74266e4fe3233b4534c46b4864f58a9e63200
Reviewed-on: https://gerrit.libreoffice.org/71201
Reviewed-by: Ashod Nakashian <ashnakash at gmail.com>
Tested-by: Ashod Nakashian <ashnakash at gmail.com>
diff --git a/scripts/perftrace.pl b/scripts/perftrace.pl
index 747039963..15344b7a9 100755
--- a/scripts/perftrace.pl
+++ b/scripts/perftrace.pl
@@ -72,19 +72,34 @@ sub offset_microsecs($)
# 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 => "^lokit_.*",
- start => 'Loading url .*',
+ {
+ name => 'Initialize wsd.',
+ type => 'INF',
+ emitter => '^loolwsd$',
+ start => 'Initializing wsd.\.*',
+ end => 'Listening to prisoner connections.*' },
+ {
+ name => 'initialize forkit',
+ type => 'INF',
+ emitter => '^forkit$',
+ start => 'Initializing frk.\.*',
+ end => 'ForKit process is ready.*' },
+ { # Load
+ emitter => "^lokit_",
+ start => 'Loading url.*for session',
end => '^Document loaded in .*ms$' },
- # FIXME: add save too ...
+ { # Save - save to a local file.
+ name => 'save to local',
+ emitter => '^docbroker',
+ start => '^Saving doc',
+ end => 'unocommandresult:.*commandName.*\.uno:Save.*success'
+ },
+ { # Save - to storage
+ name => 'save to storage',
+ emitter => '^docbroker',
+ start => '^Saving to storage docKey',
+ end => '^(Saved docKey.* to URI)|(Save skipped as document)',
+ }
);
# Idle events
@@ -118,9 +133,9 @@ sub get_event_type($$$)
return '';
}
-sub consume($$$$$$$$)
+sub consume($$$$$$$$$)
{
- my ($proc, $pid, $tid, $time, $emitter, $type, $message, $line) = @_;
+ my ($lineno, $proc, $pid, $tid, $time, $emitter, $type, $message, $line) = @_;
$pid = int($pid);
$tid = int($tid);
@@ -145,21 +160,25 @@ sub consume($$$$$$$$)
my $handled = 0;
foreach my $match (@event_pairs) {
- next if ($type ne $match->{type});
+ next if (defined $match->{type} && $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";
+ my $key;
+ $key = $type if (defined $match->{type});
+ $key .= $emitter.$start;
+ if ($message =~ m/$start/s) {
+# print STDERR "matched start $key -> $message vs. $start\n";
+ defined $pair_starts{$key} && die "key $key - event $start ($end) starts and fails to finish at line: $lineno";
$pair_starts{$key} = $time;
last;
- } elsif ($message =~ m/$end/) {
- defined $pair_starts{$key} || die "event $start ($end) ends but failed to start";
+ } elsif ($message =~ m/$end/s) {
+# print STDERR "matched end $key -> $message vs. $end\n";
+ defined $pair_starts{$key} || die "key $key - event $start ($end) ends but failed to start at line: $lineno";
- my $content_e = escape($start);
- my $title_e = escape($line);
+ my $content_e = escape($start . $line);
+ my $title_e = escape($match->{name});
my $start_time = $pair_starts{$key};
my $end_time = $time;
@@ -177,6 +196,7 @@ sub consume($$$$$$$$)
"end: new Date('$log_start_date $end_time'), ".
"content: '$content_e', title: '$title_e'}";
}
+ $pair_starts{$key} = undef;
last;
}
}
@@ -304,7 +324,7 @@ while (my $line = $input[$lineno++]) {
# wsd-26974-26974 2019-03-27 03:45:46.735736 [ loolwsd ] INF Initializing wsd. Local time: Wed 2019-03-27 03:45:46+0000. Log level is [8].| common/Log.cpp:191
if ($line =~ m/^(\w+)-(\d+)-(\d+)\s+\S+\s+(\S+)\s+\[\s+(\S+)\s+\]\s+(\S+)\s+(.+)\|\s+(\S+)$/) {
- consume($1, $2, $3, $4, $5, $6, $7, $8);
+ consume($lineno, $1, $2, $3, $4, $5, $6, $7, $8);
} 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);
@@ -319,7 +339,7 @@ while (my $line = $input[$lineno++]) {
$message = $message . $next;
}
}
- consume($proc, $pid, $tid, $time, $emitter, $type, $message, $line);
+ consume($lineno, $proc, $pid, $tid, $time, $emitter, $type, $message, $line);
} else {
die "Poorly formed line on " . ($lineno - 1) . " - is logging.file.flush set to true ? '$line'\n";
}
commit 5ecb51f03611f507560073b881f6a6afa3c54345
Author: Michael Meeks <michael.meeks at collabora.com>
AuthorDate: Thu Apr 4 20:01:19 2019 +0100
Commit: Ashod Nakashian <ashnakash at gmail.com>
CommitDate: Wed Apr 24 14:38:58 2019 +0200
perftrace: annotate start events as idle as well.
Change-Id: Iaf603101426caca1f48ebe10918170287aee006d
Reviewed-on: https://gerrit.libreoffice.org/71200
Reviewed-by: Ashod Nakashian <ashnakash at gmail.com>
Tested-by: Ashod Nakashian <ashnakash at gmail.com>
diff --git a/kit/Kit.cpp b/kit/Kit.cpp
index 76e41b4b3..fddda1292 100644
--- a/kit/Kit.cpp
+++ b/kit/Kit.cpp
@@ -1344,6 +1344,8 @@ public:
}
else
tileQueue->put("callback " + std::to_string(descriptor->getViewId()) + ' ' + std::to_string(type) + ' ' + payload);
+
+ LOG_TRC("Document::ViewCallback end.");
}
private:
diff --git a/scripts/perftrace.pl b/scripts/perftrace.pl
index 2c55951e7..747039963 100755
--- a/scripts/perftrace.pl
+++ b/scripts/perftrace.pl
@@ -88,21 +88,33 @@ my @event_pairs = (
);
# Idle events
-my @idle_types = (
+my @idleend_types = (
'^Poll completed'
);
+my @idlestart_types = (
+ '^Document::ViewCallback end\.'
+ );
+
my %pair_starts;
my %proc_names;
-sub get_event_type($$$)
+sub match_list($@)
{
- my ($type, $emitter, $message) = @_;
- foreach my $match (@idle_types) {
+ my $message = shift;
+ while (my $match = shift) {
if ($message =~ m/$match/) {
- return 'idle';
+ return 1;
}
}
+ return 0;
+}
+
+sub get_event_type($$$)
+{
+ my ($type, $emitter, $message) = @_;
+ return 'idle_end' if (match_list($message, @idleend_types));
+ return 'idle_start' if (match_list($message, @idlestart_types));
return '';
}
@@ -110,6 +122,9 @@ sub consume($$$$$$$$)
{
my ($proc, $pid, $tid, $time, $emitter, $type, $message, $line) = @_;
+ $pid = int($pid);
+ $tid = int($tid);
+
# print STDERR "$emitter, $type, $time, $message, $line\n";
$time = offset_microsecs($time) if ($json); # microseconds from start
@@ -118,13 +133,13 @@ sub consume($$$$$$$$)
if (!defined $emitters{$emitter}) {
$emitters{$emitter} = (scalar keys %emitters) + 1;
if ($json) {
- push @events, "{\"name\": \"thread_name\", \"ph\": \"M\", \"pid\": $pid, \"tid\": $tid, \"args\": { \"name\" : \"$emitter\" } }";
+ push @events, "{\"name\": \"thread_name\", \"thread_sort_index\": -$tid, \"ph\": \"M\", \"pid\": $pid, \"tid\": $tid, \"args\": { \"name\" : \"$emitter\" } }";
}
}
if (!defined $proc_names{$pid}) {
$proc_names{$pid} = 1;
if ($json) {
- push @events, "{\"name\": \"process_name\", \"ph\": \"M\", \"pid\": $pid, \"args\": { \"name\" : \"$proc\" } }";
+ push @events, "{\"name\": \"process_name\", \"process_sort_index\": -$pid, \"ph\": \"M\", \"pid\": $pid, \"args\": { \"name\" : \"$proc\" } }";
}
}
@@ -178,17 +193,16 @@ sub consume($$$$$$$$)
$dur = $time - $last_times{$key};
my $idx = $last_event_idx{$key};
- 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";
- }
+ $dur = 1 if ($event_type eq 'idle_end' && $dur > 1);
+ $events[$idx] =~ s/\"dur\":10/\"dur\":$dur/;
}
$last_times{$key} = $time;
$last_event_idx{$key} = scalar @events;
my $json_type = "\"ph\":\"X\", \"s\":\"p\"";
- push @events, "{\"pid\":$pid, \"tid\":$tid, \"ts\":$time, \"dur\":10, $json_type, \"name\":\"$content_e\" }";
+ my $replace_dur = 10;
+ $replace_dur = 1 if ($event_type eq 'idle_start'); # miss the regexp
+ push @events, "{\"pid\":$pid, \"tid\":$tid, \"ts\":$time, \"dur\":$replace_dur, $json_type, \"name\":\"$content_e\" }";
}
else
{
More information about the Libreoffice-commits
mailing list