[Libreoffice-commits] online.git: Branch 'distro/collabora/collabora-online-4' - 2 commits - scripts/perftrace.pl

Libreoffice Gerrit user logerrit at kemper.freedesktop.org
Wed Apr 24 12:38:03 UTC 2019


 scripts/perftrace.pl |  159 +++++++++++++++++++++++++++++++++++++++++++++------
 1 file changed, 143 insertions(+), 16 deletions(-)

New commits:
commit 03eaa1deb41cdc704c54a2dab3a228ac6203019b
Author:     Michael Meeks <michael.meeks at collabora.com>
AuthorDate: Tue Apr 2 20:17:33 2019 +0100
Commit:     Ashod Nakashian <ashnakash at gmail.com>
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 <ashnakash at gmail.com>
    Tested-by: Ashod Nakashian <ashnakash at gmail.com>

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 <michael.meeks at collabora.com>
AuthorDate: Fri Mar 29 09:36:46 2019 +0000
Commit:     Ashod Nakashian <ashnakash at gmail.com>
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 <ashnakash at gmail.com>
    Tested-by: Ashod Nakashian <ashnakash at gmail.com>

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()


More information about the Libreoffice-commits mailing list