scripts/perftrace.pl | 159 +++++++++++++++++++++++++++++++++++++++++++++------ 1 file changed, 143 insertions(+), 16 deletions(-)
New commits: commit 03eaa1deb41cdc704c54a2dab3a228ac6203019b Author: Michael Meeks <[email protected]> AuthorDate: Tue Apr 2 20:17:33 2019 +0100 Commit: Ashod Nakashian <[email protected]> CommitDate: Wed Apr 24 14:37:55 2019 +0200 perftrace: output in Trace Event Format too and by default. Change-Id: I964f869d953234a83066c5d34f43abfc22933b46 Reviewed-on: https://gerrit.libreoffice.org/71195 Reviewed-by: Ashod Nakashian <[email protected]> Tested-by: Ashod Nakashian <[email protected]> diff --git a/scripts/perftrace.pl b/scripts/perftrace.pl index d050d9fe3..efb795dbe 100755 --- a/scripts/perftrace.pl +++ b/scripts/perftrace.pl @@ -12,24 +12,59 @@ use strict; my @input = <STDIN>; my %emitters; -my $log_date; +my $log_start_date; +my $log_start_time; +my @log_start; my @events; +my $json = 1; sub escape($) { my $str = shift; $str =~ s/\\/\\\\/g; - $str =~ s/\$/\\\$/g; - $str =~ s/\'/\\'/g; - $str =~ s/\"/\\"/g; - $str =~ s/\&/&/g; - $str =~ s/\#/#/g; - $str =~ s/\>/>/g; - $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 $time = shift; + $time =~ m/^(\d\d):(\d\d):(\d\d)\.(\d+)$/ || die "Invalid time: '$time'"; + return ($1, $2, $3, $4); +} + +sub offset_microsecs($) +{ + my @time = splittime(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 * 1000000; + $usec = $usec + $time[3]; + + return $usec; +} + # Delimit spans of time: my @pairs = ( { type => 'INF', @@ -50,6 +85,8 @@ sub consume($$$$$) # print STDERR "$emitter, $type, $time, $message, $line\n"; + $time = offset_microsecs($time) if ($json); # microseconds from start + # accumulate all threads / processes if (!defined $emitters{$emitter}) { $emitters{$emitter} = (scalar keys %emitters) + 1; @@ -70,29 +107,63 @@ sub consume($$$$$) } elsif ($message =~ m/$end/) { defined $pair_starts{$key} || die "event $start ($end) ends but failed to start"; - my $id = (scalar @events) + 1; - my $content_e = escape($start); my $title_e = escape($line); my $start_time = $pair_starts{$key}; my $end_time = $time; - push @events, "{id: $id, group: $emitters{$emitter}, ". - "start: new Date('$log_date $start_time'), ". - "end: new Date('$log_date $end_time'), ". - "content: '$content_e', title: '$title_e'}"; + + if ($json) + { + my $dur = $end_time - $start_time; + my $ms = int ($dur / 1000.0); + push @events, "{\"pid\":$emitters{$emitter}, \"tid\":1, \"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'}"; + } last; } } my $content_e = escape($message. " " . $line); - my $id = (scalar @events) + 1; - push @events, "{id: $id, group: $emitters{$emitter}, ". - "start: new Date('$log_date $time'), ". - "end: new Date('$log_date $time)') + new Date(1), ". - "content: '$content_e', title: ''}"; + if ($json) + { + push @events, "{\"pid\":$emitters{$emitter}, \"tid\":1, \"ts\":$time, \"ph\":\"i\", \"s\":\"p\", \"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 emit() +# 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) { @@ -145,10 +216,12 @@ HTMLEND } # wsd-29885-29885 2019-03-27 ... -if ($input[0] =~ m/^\S+\s([\d-]+)\s+/) +if ($input[0] =~ m/^\S+\s([\d-]+)\s+([\d:\.]+)\s+/) { - $log_date = $1; - print STDERR "reading log from $log_date\n"; + $log_start_date = $1; + $log_start_time = $2; + @log_start = splittime($2); + print STDERR "reading log from $log_start_date / $log_start_time\n"; } else { die "Malformed log line: $input[0]"; } @@ -182,4 +255,9 @@ while (my $line = shift @input) { } } -emit(); +if ($json) { + emit_json(); +} else { + emit_js(); +} + commit ba6fe4dd00c2e6c791b9d1711c17f8b14a61a542 Author: Michael Meeks <[email protected]> AuthorDate: Fri Mar 29 09:36:46 2019 +0000 Commit: Ashod Nakashian <[email protected]> CommitDate: Wed Apr 24 14:37:46 2019 +0200 perftrace: start to annotate common spans. Change-Id: I90e9939ddc7dedfb24fd608f13ea31a2863ebe3e Reviewed-on: https://gerrit.libreoffice.org/71194 Reviewed-by: Ashod Nakashian <[email protected]> Tested-by: Ashod Nakashian <[email protected]> diff --git a/scripts/perftrace.pl b/scripts/perftrace.pl index 90fe06105..d050d9fe3 100755 --- a/scripts/perftrace.pl +++ b/scripts/perftrace.pl @@ -18,29 +18,78 @@ my @events; sub escape($) { my $str = shift; + $str =~ s/\\/\\\\/g; $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; } +# Delimit spans of time: +my @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.*' + } +); +my %pair_starts; + sub consume($$$$$) { my ($time, $emitter, $type, $message, $line) = @_; + # print STDERR "$emitter, $type, $time, $message, $line\n"; + + # accumulate all threads / processes if (!defined $emitters{$emitter}) { $emitters{$emitter} = (scalar keys %emitters) + 1; } - return if ($type eq 'TRC' || $type eq 'DBG' || $type eq 'ERR'); + my $handled = 0; + foreach my $match (@pairs) { + next if ($type ne $match->{type}); + next if (!($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"; + $pair_starts{$key} = $time; + last; + } elsif ($message =~ m/$end/) { + defined $pair_starts{$key} || die "event $start ($end) ends but failed to start"; + + my $id = (scalar @events) + 1; + + my $content_e = escape($start); + my $title_e = escape($line); + my $start_time = $pair_starts{$key}; + my $end_time = $time; + push @events, "{id: $id, group: $emitters{$emitter}, ". + "start: new Date('$log_date $start_time'), ". + "end: new Date('$log_date $end_time'), ". + "content: '$content_e', title: '$title_e'}"; + last; + } + } + my $content_e = escape($message. " " . $line); my $id = (scalar @events) + 1; - # omitted 'end' - should really synthesize more cleverly here. title: '$message_e' - my $message_e = escape($message); - my $line_e = escape($line); - push @events, "{id: $id, group: $emitters{$emitter}, start: new Date('$log_date $time'), content: '$line_e'}"; - -# print STDERR "$emitter, $type, $time, $message, $line\n"; + push @events, "{id: $id, group: $emitters{$emitter}, ". + "start: new Date('$log_date $time'), ". + "end: new Date('$log_date $time)') + new Date(1), ". + "content: '$content_e', title: ''}"; } sub emit() _______________________________________________ Libreoffice-commits mailing list [email protected] https://lists.freedesktop.org/mailman/listinfo/libreoffice-commits
