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 | 394 +++++++++++++++++++ tools/KitClient.cpp | 1 7 files changed, 411 insertions(+), 1 deletion(-)
New commits: commit 4eb8f982e05f5096ed7a2f170f0f54e63dfffb44 Author: Michael Meeks <[email protected]> AuthorDate: Fri Apr 12 20:16:44 2019 +0100 Commit: Andras Timar <[email protected]> CommitDate: Thu Jun 13 13:43:44 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 <[email protected]> Tested-by: Ashod Nakashian <[email protected]> Reviewed-on: https://gerrit.libreoffice.org/72872 Tested-by: Andras Timar <[email protected]> diff --git a/bundled/include/LibreOfficeKit/LibreOfficeKitEnums.h b/bundled/include/LibreOfficeKit/LibreOfficeKitEnums.h index b82e28d93..33d235af8 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 9617a96b7..c4ec709c9 100644 --- a/kit/ChildSession.cpp +++ b/kit/ChildSession.cpp @@ -2152,6 +2152,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 05dbdc722..02ed30337 100644 --- a/kit/Kit.cpp +++ b/kit/Kit.cpp @@ -1247,7 +1247,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) { @@ -1259,6 +1259,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 new file mode 100755 index 000000000..c779b95b5 --- /dev/null +++ b/scripts/perftrace.pl @@ -0,0 +1,394 @@ +#!/usr/bin/perl -w +# +# This file is part of the LibreOffice project. +# +# This Source Code Form is subject to the terms of the Mozilla Public +# License, v. 2.0. If a copy of the MPL was not distributed with this +# file, You can obtain one at http://mozilla.org/MPL/2.0/. +# + +use strict; + +my @input = <STDIN>; + +my %emitters; +my $log_start_date; +my $log_start_time; +my @log_start; +my @events; + +my %last_times; # $time for last key +my %last_event_idx; # $events[$idx] for last key + +# Google Chrome Trace Event Format if set +my $json = 1; + +sub escape($) +{ + my $str = shift; + $str =~ s/\\/\\\\/g; + + if ($json) + { + $str =~ s/\t/\\t/g; + $str =~ s/\"/\\"/g; # json - and html + } + else + { + $str =~ s/\$/\\\$/g; + $str =~ s/\'/\\'/g; + $str =~ s/\"/\\"/g; + $str =~ s/\&/&/g; + $str =~ s/\#/#/g; + $str =~ s/\>/>/g; + $str =~ s/\</</g; + } + $str =~ s/[\r\n]+/\\n/g; + return $str; +} + +# 23:34:16.123456 +sub splittime($$) +{ + my $lineno = shift; + my $time = shift; + $time =~ m/^(\d\d):(\d\d):(\d\d)\.(\d+)$/ || die "Invalid time at line $lineno: '$time'"; + return ($1, $2, $3, $4); +} + +sub offset_microsecs($$) +{ + my @time = splittime(shift, shift); + + my $usec = 0 + $time[0] - $log_start[0]; + $usec = $usec * 60; + $usec = $usec + $time[1] - $log_start[1]; + $usec = $usec * 60; + $usec = $usec + $time[2] - $log_start[2]; + $usec = $usec * 1000 * 1000; + $usec = $usec + $time[3]; + + return $usec; +} + +# Important things that happen in pairs +my @event_pairs = ( + { + 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$' }, + { # 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 +my @idleend_types = ( + '^Poll completed' + ); + +my @idlestart_types = ( + '^Document::ViewCallback end\.' + ); + +my %pair_starts; +my %proc_names; + +sub match_list($@) +{ + my $message = shift; + while (my $match = shift) { + if ($message =~ m/$match/) { + 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 ''; +} + +sub consume($$$$$$$$$) +{ + my ($lineno, $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($lineno, $time) if ($json); # microseconds from start + + # accumulate all threads / processes + if (!defined $emitters{$emitter}) { + $emitters{$emitter} = (scalar keys %emitters) + 1; + if ($json) { + 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\", \"process_sort_index\": -$pid, \"ph\": \"M\", \"pid\": $pid, \"args\": { \"name\" : \"$proc\" } }"; + } + } + + 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}); + next if (defined $match->{emitter} && !($emitter =~ m/$match->{emitter}/)); + + my $start = $match->{start}; + my $end = $match->{end}; + 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/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 . $line); + my $title_e = escape($match->{name}); + 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'}"; + } + $pair_starts{$key} = undef; + 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}; + + $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\""; + 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 + { + my $id = (scalar @events) + 1; + push @events, "{id: $id, group: $emitters{$emitter}, ". + "start: new Date('$log_start_date $time'), ". + "end: new Date('$log_start_date $time)') + new Date(1), ". + "content: '$content_e', title: ''}"; + } +} + +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() +{ + my $events_json = join(",\n", @events); + + print STDOUT << "JSONEND" +{ +"traceEvents": [ + $events_json +], +"displayTimeUnit":"ms", +"meta_user": "online", +"meta_cpu_count" : 8 +} +JSONEND +; +} + +sub emit_js() +{ + my @groups; + foreach my $emitter (sort { $emitters{$a} <=> $emitters{$b} } keys %emitters) { + push @groups, "{id: $emitters{$emitter}, content: '$emitter'}"; + } + + my $groups_json = join(",\n", @groups); + my $items_json = join(",\n", @events); + + my $start_time = "2019-03-27 04:34:57.807344"; + my $end_time = "2019-03-27 04:35:28.911621"; + + print STDOUT <<"HTMLEND" +<html> +<head> + <title>Online timeline / profile</title> + <script src="http://visjs.org/dist/vis.js";></script> + <link href="http://visjs.org/dist/vis-timeline-graph2d.min.css"; rel="stylesheet" type="text/css" /> +</head> + +<body onresize="/*timeline.checkResize();*/"> + +<h1>Online timeline / profile</h1> + +<div id="profile"></div> + +<script> + var groups = new vis.DataSet([ $groups_json ]); + var items = new vis.DataSet([ $items_json ]); + + var options = { + stack: false, + start: new Date('$start_time'), + end: new Date('$end_time'), + editable: false, + margin: { item: 10, axis: 5 }, + orientation: 'top' + }; + + var container = document.getElementById('profile'); + timeline = new vis.Timeline(container, null, options); + timeline.setGroups(groups); + timeline.setItems(items); + +</script> +</body> +</html> +HTMLEND +; +} + +# wsd-29885-29885 2019-03-27 ... +if ($input[0] =~ m/^\S+\s([\d-]+)\s+([\d:\.]+)\s+/) +{ + $log_start_date = $1; + $log_start_time = $2; + @log_start = splittime(0, $2); + print STDERR "reading log from $log_start_date / $log_start_time\n"; +} else { + die "Malformed log line or no input: $input[0]"; +} + +# parse all the lines +my $lineno = 0; +while (my $line = $input[$lineno++]) { + my ($pevent, $pdetail); + + $line =~ s/\r*\n*//g; + + # 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($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); + while (my $next = $input[$lineno++]) { + # ... | kit/Kit.cpp:1272 + if ($next =~ m/^(.*)\|\s+(\S+)$/) + { + $message = $message . $1; + $line = $2; + last; + } else { + $message = $message . $next; + } + } + + # 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"; + } +} + +if ($json) { + emit_json(); +} else { + emit_js(); +} + 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 [email protected] https://lists.freedesktop.org/mailman/listinfo/libreoffice-commits
