[Libreoffice-commits] online.git: Branch 'distro/collabora/collabora-online-4' - bundled/include 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
Wed Apr 24 12:39:37 UTC 2019
bundled/include/LibreOfficeKit/LibreOfficeKitEnums.h | 6 ++
kit/ChildSession.cpp | 1
kit/ForKit.cpp | 4 +
kit/Kit.cpp | 4 +
kit/KitHelper.hpp | 2
scripts/perftrace.pl | 57 ++++++++++++++++---
tools/KitClient.cpp | 1
7 files changed, 66 insertions(+), 9 deletions(-)
New commits:
commit f1369669850ccbba19592124932cb932479c7e63
Author: Michael Meeks <michael.meeks at collabora.com>
AuthorDate: Fri Apr 12 20:16:44 2019 +0100
Commit: Ashod Nakashian <ashnakash at gmail.com>
CommitDate: Wed Apr 24 14:39:19 2019 +0200
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
Reviewed-on: https://gerrit.libreoffice.org/71202
Reviewed-by: Ashod Nakashian <ashnakash at gmail.com>
Tested-by: Ashod Nakashian <ashnakash at gmail.com>
diff --git a/bundled/include/LibreOfficeKit/LibreOfficeKitEnums.h b/bundled/include/LibreOfficeKit/LibreOfficeKitEnums.h
index aae23e319..1a2013b2a 100644
--- a/bundled/include/LibreOfficeKit/LibreOfficeKitEnums.h
+++ b/bundled/include/LibreOfficeKit/LibreOfficeKitEnums.h
@@ -611,6 +611,12 @@ typedef enum
* On-load notification of the document signature status.
*/
LOK_CALLBACK_SIGNATURE_STATUS = 40,
+
+ /**
+ * Profiling tracing information single string of multiple lines
+ * containing <pid> <timestamp> and zone start/stop information
+ */
+ LOK_CALLBACK_PROFILE_FRAME = 41
}
LibreOfficeKitCallbackType;
diff --git a/kit/ChildSession.cpp b/kit/ChildSession.cpp
index 91398619a..768b514bf 100644
--- a/kit/ChildSession.cpp
+++ b/kit/ChildSession.cpp
@@ -2256,6 +2256,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 38c15d215..9b3571efb 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 fddda1292..0609cb5b2 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 f8ec0c9a3..d3a9efd96 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 15344b7a9..c779b95b5 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