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.me...@collabora.com> AuthorDate: Fri Apr 12 20:16:44 2019 +0100 Commit: Michael Meeks <michael.me...@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; _______________________________________________ Libreoffice-commits mailing list libreoffice-comm...@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/libreoffice-commits