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

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


 net/Socket.hpp       |    1 
 scripts/perftrace.pl |  221 ++++++++++++++++++++++++++++++---------------------
 2 files changed, 133 insertions(+), 89 deletions(-)

New commits:
commit c3a7c423d80febeab6d4a1e0acd19b27b7131362
Author:     Michael Meeks <michael.meeks at collabora.com>
AuthorDate: Thu Apr 4 18:55:07 2019 +0100
Commit:     Ashod Nakashian <ashnakash at gmail.com>
CommitDate: Wed Apr 24 14:38:49 2019 +0200

    perftrace: Annotate idleness and render it better as gaps.
    
    Change-Id: If4d7853d02ca736f8cab12bd9dcc7c4b60ec7d27
    Reviewed-on: https://gerrit.libreoffice.org/71199
    Reviewed-by: Ashod Nakashian <ashnakash at gmail.com>
    Tested-by: Ashod Nakashian <ashnakash at gmail.com>

diff --git a/net/Socket.hpp b/net/Socket.hpp
index 2f0217d76..41c15c3b9 100644
--- a/net/Socket.hpp
+++ b/net/Socket.hpp
@@ -485,6 +485,7 @@ public:
         int rc;
         do
         {
+            LOG_TRC("Poll start");
 #ifndef MOBILEAPP
             rc = ::poll(&_pollFds[0], size + 1, std::max(timeoutMaxMs,0));
 #else
diff --git a/scripts/perftrace.pl b/scripts/perftrace.pl
index 32c0f0a71..2c55951e7 100755
--- a/scripts/perftrace.pl
+++ b/scripts/perftrace.pl
@@ -30,18 +30,18 @@ sub escape($)
 
     if ($json)
     {
-	$str =~ s/\t/\\t/g;
-	$str =~ s/\"/\\"/g; # json - and html
+        $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/\$/\\\$/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;
@@ -70,21 +70,42 @@ sub offset_microsecs($)
     return $usec;
 }
 
-# Delimit spans of time:
-my @pairs = (
+# 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 => 'loolwsd',
-      start => 'Initializing wsd.\.*',
-      end => 'Listening to prisoner connections.*' },
-    { type => 'INF',
-      emitter => 'forkit',
-      start => 'Initializing frk.\.*',
-      end => 'ForKit process is ready.*'
-    }
-);
+      emitter => "^lokit_.*",
+      start => 'Loading url .*',
+      end => '^Document loaded in .*ms$' },
+    # FIXME: add save too ...
+    );
+
+# Idle events
+my @idle_types = (
+    '^Poll completed'
+    );
+
 my %pair_starts;
 my %proc_names;
 
+sub get_event_type($$$)
+{
+    my ($type, $emitter, $message) = @_;
+    foreach my $match (@idle_types) {
+        if ($message =~ m/$match/) {
+            return 'idle';
+        }
+    }
+    return '';
+}
+
 sub consume($$$$$$$$)
 {
     my ($proc, $pid, $tid, $time, $emitter, $type, $message, $line) = @_;
@@ -95,78 +116,87 @@ sub consume($$$$$$$$)
 
     # accumulate all threads / processes
     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\" } }";
-	}
+        $emitters{$emitter} = (scalar keys %emitters) + 1;
+        if ($json) {
+            push @events, "{\"name\": \"thread_name\", \"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\" } }";
-	}
+        $proc_names{$pid} = 1;
+        if ($json) {
+            push @events, "{\"name\": \"process_name\", \"ph\": \"M\", \"pid\": $pid, \"args\": { \"name\" : \"$proc\" } }";
+        }
     }
 
     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 $content_e = escape($start);
-	    my $title_e = escape($line);
-	    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'}";
-	    }
-	    last;
-	}
+    foreach my $match (@event_pairs) {
+       next if ($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";
+           $pair_starts{$key} = $time;
+           last;
+       } elsif ($message =~ m/$end/) {
+           defined $pair_starts{$key} || die "event $start ($end) ends but failed to start";
+
+           my $content_e = escape($start);
+           my $title_e = escape($line);
+           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'}";
+           }
+           last;
+       }
     }
 
     my $content_e = escape($message. " " . $line);
     if ($json)
     {
-	# 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};
-	    $events[$idx] =~ s/\"dur\":100/\"dur\":$dur/;
-	}
-	$last_times{$key} = $time;
-	$last_event_idx{$key} = scalar @events;
-	push @events, "{\"pid\":$pid, \"tid\":$tid, \"ts\":$time, \"dur\":100, \"ph\":\"X\", \"s\":\"p\", \"name\":\"$content_e\" }";
+        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};
+
+            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";
+            }
+        }
+        $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\" }";
     }
     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: ''}";
+        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: ''}";
     }
 }
 
@@ -192,7 +222,7 @@ sub emit_js()
 {
     my @groups;
     foreach my $emitter (sort { $emitters{$a} <=> $emitters{$b} } keys %emitters) {
-	push @groups, "{id: $emitters{$emitter}, content: '$emitter'}";
+        push @groups, "{id: $emitters{$emitter}, content: '$emitter'}";
     }
 
     my $groups_json = join(",\n", @groups);
@@ -252,31 +282,32 @@ if ($input[0] =~ m/^\S+\s([\d-]+)\s+([\d:\.]+)\s+/)
 }
 
 # parse all the lines
-while (my $line = shift @input) {
+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($1, $2, $3, $4, $5, $6, $7, $8);
+        consume($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 =  shift @input) {
-	    # ... | kit/Kit.cpp:1272
-	    if ($next =~ m/^(.*)\|\s+(\S+)$/)
-	    {
-		$message = $message . $1;
-		$line = $2;
-		last;
-	    } else {
-		$message = $message . $next;
-	    }
-	}
-	consume($proc, $pid, $tid, $time, $emitter, $type, $message, $line);
+        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;
+            }
+        }
+        consume($proc, $pid, $tid, $time, $emitter, $type, $message, $line);
     } else {
-	die "Poorly formed line - is logging.file.flush set to true ? '$line'\n";
+        die "Poorly formed line on " . ($lineno - 1) . " - is logging.file.flush set to true ? '$line'\n";
     }
 }
 
commit 0a3834233bb113f87acdbe8520535786cb5c8620
Author:     Michael Meeks <michael.meeks at collabora.com>
AuthorDate: Wed Apr 3 21:34:47 2019 +0100
Commit:     Ashod Nakashian <ashnakash at gmail.com>
CommitDate: Wed Apr 24 14:38:39 2019 +0200

    perftrace: extend linear events duration to the next event.
    
    Change-Id: I4ab31a6a71b3efcc366ca15e15d513f73205ca37
    Reviewed-on: https://gerrit.libreoffice.org/71198
    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 f7c6e6fa3..32c0f0a71 100755
--- a/scripts/perftrace.pl
+++ b/scripts/perftrace.pl
@@ -17,6 +17,9 @@ 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;
 
@@ -61,7 +64,7 @@ sub offset_microsecs($)
     $usec = $usec + $time[1] - $log_start[1];
     $usec = $usec * 60;
     $usec = $usec + $time[2] - $log_start[2];
-    $usec = $usec * 1000000;
+    $usec = $usec * 1000 * 1000;
     $usec = $usec + $time[3];
 
     return $usec;
@@ -94,13 +97,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\", \"ph\": \"M\", \"pid\": $pid, \"tid\": $tid, \"args\": { \"name\" : \"$emitter\" } }";
 	}
     }
-    if (!defined $proc_names{$proc}) {
-	$proc_names{$proc} = (scalar keys %proc_names) + 1;
+    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\", \"ph\": \"M\", \"pid\": $pid, \"args\": { \"name\" : \"$proc\" } }";
 	}
     }
 
@@ -143,10 +146,19 @@ sub consume($$$$$$$$)
     }
 
     my $content_e = escape($message. " " . $line);
-    # Hack give all events a 10ms duration - better to use the gap to the next event though.
     if ($json)
     {
-	push @events, "{\"pid\":$pid, \"tid\":$tid, \"ts\":$time, \"dur\":10000, \"ph\":\"X\", \"s\":\"p\", \"name\":\"$content_e\" }";
+	# 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};
+	    $events[$idx] =~ s/\"dur\":100/\"dur\":$dur/;
+	}
+	$last_times{$key} = $time;
+	$last_event_idx{$key} = scalar @events;
+	push @events, "{\"pid\":$pid, \"tid\":$tid, \"ts\":$time, \"dur\":100, \"ph\":\"X\", \"s\":\"p\", \"name\":\"$content_e\" }";
     }
     else
     {


More information about the Libreoffice-commits mailing list