kit/Kit.cpp | 2 scripts/perftrace.pl | 108 +++++++++++++++++++++++++++++++++------------------ 2 files changed, 73 insertions(+), 37 deletions(-)
New commits: commit 977aed538437f391dcc3c7fb5521eb0decd6dc3b Author: Michael Meeks <[email protected]> AuthorDate: Fri Apr 5 17:51:02 2019 +0100 Commit: Ashod Nakashian <[email protected]> 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 <[email protected]> Tested-by: Ashod Nakashian <[email protected]> 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 <[email protected]> AuthorDate: Thu Apr 4 20:01:19 2019 +0100 Commit: Ashod Nakashian <[email protected]> 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 <[email protected]> Tested-by: Ashod Nakashian <[email protected]> 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 { _______________________________________________ Libreoffice-commits mailing list [email protected] https://lists.freedesktop.org/mailman/listinfo/libreoffice-commits
