[Libreoffice-commits] online.git: Branch 'distro/collabora/collabora-online-4' - bundled/include kit/ChildSession.cpp kit/ForKit.cpp kit/Kit.cpp kit/KitHelper.hpp scripts/perftrace.pl tools/KitClient.cpp

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


 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                                 |   57 ++++++++++++++++---
 tools/KitClient.cpp                                  |    1 
 7 files changed, 66 insertions(+), 9 deletions(-)

New commits:
commit f1369669850ccbba19592124932cb932479c7e63
Author:     Michael Meeks <michael.meeks at collabora.com>
AuthorDate: Fri Apr 12 20:16:44 2019 +0100
Commit:     Ashod Nakashian <ashnakash at gmail.com>
CommitDate: Wed Apr 24 14:39:19 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 <ashnakash at gmail.com>
    Tested-by: Ashod Nakashian <ashnakash at gmail.com>

diff --git a/bundled/include/LibreOfficeKit/LibreOfficeKitEnums.h b/bundled/include/LibreOfficeKit/LibreOfficeKitEnums.h
index aae23e319..1a2013b2a 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 91398619a..768b514bf 100644
--- a/kit/ChildSession.cpp
+++ b/kit/ChildSession.cpp
@@ -2256,6 +2256,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 fddda1292..0609cb5b2 100644
--- a/kit/Kit.cpp
+++ b/kit/Kit.cpp
@@ -1235,7 +1235,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)
             {
@@ -1247,6 +1247,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 f8ec0c9a3..d3a9efd96 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
index 15344b7a9..c779b95b5 100755
--- a/scripts/perftrace.pl
+++ b/scripts/perftrace.pl
@@ -48,16 +48,17 @@ sub escape($)
 }
 
 # 23:34:16.123456
-sub splittime($)
+sub splittime($$)
 {
+    my $lineno = shift;
     my $time = shift;
-    $time =~ m/^(\d\d):(\d\d):(\d\d)\.(\d+)$/ || die "Invalid time: '$time'";
+    $time =~ m/^(\d\d):(\d\d):(\d\d)\.(\d+)$/ || die "Invalid time at line $lineno: '$time'";
     return ($1, $2, $3, $4);
 }
 
-sub offset_microsecs($)
+sub offset_microsecs($$)
 {
-    my @time = splittime(shift);
+    my @time = splittime(shift, shift);
 
     my $usec = 0  + $time[0] - $log_start[0];
     $usec = $usec * 60;
@@ -142,7 +143,7 @@ sub consume($$$$$$$$$)
 
     # print STDERR "$emitter, $type, $time, $message, $line\n";
 
-    $time = offset_microsecs($time) if ($json); # microseconds from start
+    $time = offset_microsecs($lineno, $time) if ($json); # microseconds from start
 
     # accumulate all threads / processes
     if (!defined $emitters{$emitter}) {
@@ -158,6 +159,20 @@ sub consume($$$$$$$$$)
         }
     }
 
+    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});
@@ -234,6 +249,25 @@ sub consume($$$$$$$$$)
     }
 }
 
+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()
 {
@@ -309,10 +343,10 @@ if ($input[0] =~ m/^\S+\s([\d-]+)\s+([\d:\.]+)\s+/)
 {
     $log_start_date = $1;
     $log_start_time = $2;
-    @log_start = splittime($2);
+    @log_start = splittime(0, $2);
     print STDERR "reading log from $log_start_date / $log_start_time\n";
 } else {
-    die "Malformed log line: $input[0]";
+    die "Malformed log line or no input: $input[0]";
 }
 
 # parse all the lines
@@ -339,7 +373,14 @@ while (my $line = $input[$lineno++]) {
                 $message = $message . $next;
             }
         }
-        consume($lineno, $proc, $pid, $tid, $time, $emitter, $type, $message, $line);
+
+        # 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";
     }
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;


More information about the Libreoffice-commits mailing list