[Libreoffice-commits] online.git: kit/ChildSession.cpp kit/ForKit.cpp kit/Kit.cpp kit/KitHelper.hpp scripts/perftrace.pl tools/KitClient.cpp
Libreoffice Gerrit user
logerrit at kemper.freedesktop.org
Tue Apr 16 19:46:14 UTC 2019
kit/ChildSession.cpp | 1
kit/ForKit.cpp | 4 +++
kit/Kit.cpp | 4 ++-
kit/KitHelper.hpp | 2 +
scripts/perftrace.pl | 57 +++++++++++++++++++++++++++++++++++++++++++--------
tools/KitClient.cpp | 1
6 files changed, 60 insertions(+), 9 deletions(-)
New commits:
commit 729c124b3b0a4bf385a878e13b118219cb898382
Author: Michael Meeks <michael.meeks at collabora.com>
AuthorDate: Fri Apr 12 20:16:44 2019 +0100
Commit: Michael Meeks <michael.meeks at collabora.com>
CommitDate: Tue Apr 16 20:27:37 2019 +0100
perftrace: consume PROFILE_FRAME messages and chart lok ProfileZones.
Also - enable performance tracing in the kit when we're logging at
trace level.
Change-Id: I838e8d7769b0ead8508c4482c58e0e2564dcee91
diff --git a/kit/ChildSession.cpp b/kit/ChildSession.cpp
index 88a02eb66..7a98bfe2d 100644
--- a/kit/ChildSession.cpp
+++ b/kit/ChildSession.cpp
@@ -2184,6 +2184,7 @@ void ChildSession::loKitCallback(const int type, const std::string& payload)
sendTextFrame("signaturestatus: " + payload);
break;
+ case LOK_CALLBACK_PROFILE_FRAME:
case LOK_CALLBACK_DOCUMENT_PASSWORD:
case LOK_CALLBACK_DOCUMENT_PASSWORD_TO_MODIFY:
// these are not handled here.
diff --git a/kit/ForKit.cpp b/kit/ForKit.cpp
index 1cbf59a13..fe5fd225a 100644
--- a/kit/ForKit.cpp
+++ b/kit/ForKit.cpp
@@ -528,6 +528,10 @@ int main(int argc, char** argv)
return Application::EXIT_SOFTWARE;
}
+ // Enable built in profiling dumps
+ if (Log::logger().trace())
+ ::setenv("SAL_PROFILEZONE_EVENTS", "1", 0);
+
// Initialize LoKit
if (!globalPreinit(loTemplate))
{
diff --git a/kit/Kit.cpp b/kit/Kit.cpp
index 7555ae9eb..7472446b2 100644
--- a/kit/Kit.cpp
+++ b/kit/Kit.cpp
@@ -1235,7 +1235,7 @@ public:
self->setDocumentPassword(type);
return;
}
- else if(type == LOK_CALLBACK_STATUS_INDICATOR_SET_VALUE)
+ else if (type == LOK_CALLBACK_STATUS_INDICATOR_SET_VALUE)
{
for (auto& it : self->_sessions)
{
@@ -1247,6 +1247,8 @@ public:
}
return;
}
+ else if (type == LOK_CALLBACK_PROFILE_FRAME)
+ return; // already trace dumped above.
// Broadcast leftover status indicator callbacks to all clients
self->broadcastCallbackToClients(type, payload);
diff --git a/kit/KitHelper.hpp b/kit/KitHelper.hpp
index b6225feda..88d090428 100644
--- a/kit/KitHelper.hpp
+++ b/kit/KitHelper.hpp
@@ -131,6 +131,8 @@ namespace LOKitHelper
return "CONTEXT_CHANGED";
case LOK_CALLBACK_SIGNATURE_STATUS:
return "SIGNATURE_STATUS";
+ case LOK_CALLBACK_PROFILE_FRAME:
+ return "PROFILE_FRAME";
}
assert(!"Missing LOK_CALLBACK type");
diff --git a/scripts/perftrace.pl b/scripts/perftrace.pl
index 759093613..8c8d69291 100755
--- a/scripts/perftrace.pl
+++ b/scripts/perftrace.pl
@@ -48,16 +48,17 @@ sub escape($)
}
# 23:34:16.123456
-sub splittime($)
+sub splittime($$)
{
+ my $lineno = shift;
my $time = shift;
- $time =~ m/^(\d\d):(\d\d):(\d\d)\.(\d+)$/ || die "Invalid time: '$time'";
+ $time =~ m/^(\d\d):(\d\d):(\d\d)\.(\d+)$/ || die "Invalid time at line $lineno: '$time'";
return ($1, $2, $3, $4);
}
-sub offset_microsecs($)
+sub offset_microsecs($$)
{
- my @time = splittime(shift);
+ my @time = splittime(shift, shift);
my $usec = 0 + $time[0] - $log_start[0];
$usec = $usec * 60;
@@ -142,7 +143,7 @@ sub consume($$$$$$$$$)
# print STDERR "$emitter, $type, $time, $message, $line\n";
- $time = offset_microsecs($time) if ($json); # microseconds from start
+ $time = offset_microsecs($lineno, $time) if ($json); # microseconds from start
# accumulate all threads / processes
if (!defined $emitters{$emitter}) {
@@ -158,6 +159,20 @@ sub consume($$$$$$$$$)
}
}
+ if ($type eq 'PROF') {
+ # sw::DocumentTimerManager m_aFireIdleJobsTimer: stop 0.047 ms
+ if ($message =~ m/^(.*): stop ([\d\.]+) ms$/) {
+ my $dur_ms = $2;
+ my $dur_us = $dur_ms * 1000.0;
+ my $msg = $1;
+ $time = $time - $dur_us;
+ push @events, "{\"pid\":$pid, \"tid\":$tid, \"ts\":$time, \"dur\":$dur_us, \"ph\":\"X\", \"name\":\"$msg\", \"args\":{ \"ms\":$dur_ms } }";
+ } else {
+ die "Unknown prof message: '$message'";
+ }
+ return;
+ }
+
my $handled = 0;
foreach my $match (@event_pairs) {
next if (defined $match->{type} && $type ne $match->{type});
@@ -234,6 +249,25 @@ sub consume($$$$$$$$$)
}
}
+sub parseProfileFrames($$$$$)
+{
+ my ($lineno, $proc, $pid, $emitter, $message) = @_;
+ my @lines = split(/\n/, $message);
+
+ foreach my $line (@lines) {
+ next if ($line =~ m/start$/); # all data we need is in the end.
+ if ($line =~ m/^(\d+)\s+(\d+)\.(\d+)\s+(.*$)/) {
+ my ($tid, $secs, $fractsecs, $realmsg) = ($1, $2, $3, $4);
+ # print STDERR "Profile frame '$line'\n";
+ # FIXME: silly to complicate and then re-parse this I guess ...
+ my ($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst) = gmtime($secs);
+ my $time = sprintf("%.2d:%.2d:%02.6f", $hour, $min, "$sec.$fractsecs");
+# print STDERR "time '$time' from '$secs' - " . time() . "\n";
+ consume($lineno, $proc, $pid, $tid, $time, $emitter, 'PROF', $realmsg, '');
+ }
+ }
+}
+
# Open in chrome://tracing
sub emit_json()
{
@@ -309,10 +343,10 @@ if ($input[0] =~ m/^\S+\s([\d-]+)\s+([\d:\.]+)\s+/)
{
$log_start_date = $1;
$log_start_time = $2;
- @log_start = splittime($2);
+ @log_start = splittime(0, $2);
print STDERR "reading log from $log_start_date / $log_start_time\n";
} else {
- die "Malformed log line: $input[0]";
+ die "Malformed log line or no input: $input[0]";
}
# parse all the lines
@@ -339,7 +373,14 @@ while (my $line = $input[$lineno++]) {
$message = $message . $next;
}
}
- consume($lineno, $proc, $pid, $tid, $time, $emitter, $type, $message, $line);
+
+ # Profile frames are special
+ if ($type eq 'TRC' && $emitter eq 'lo_startmain' &&
+ $message =~ /.*Document::GlobalCallback PROFILE_FRAME.*/) {
+ parseProfileFrames($lineno, $proc, $pid, $emitter, $message);
+ } else {
+ 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";
}
diff --git a/tools/KitClient.cpp b/tools/KitClient.cpp
index 6cafbe48e..bbf9f089b 100644
--- a/tools/KitClient.cpp
+++ b/tools/KitClient.cpp
@@ -84,6 +84,7 @@ extern "C"
CASE(CLIPBOARD_CHANGED);
CASE(CONTEXT_CHANGED);
CASE(SIGNATURE_STATUS);
+ CASE(PROFILE_FRAME);
#undef CASE
}
std::cout << " payload: " << payload << std::endl;
More information about the Libreoffice-commits
mailing list