net/Socket.hpp | 1 scripts/perftrace.pl | 221 ++++++++++++++++++++++++++++++--------------------- 2 files changed, 133 insertions(+), 89 deletions(-)
New commits: commit c3a7c423d80febeab6d4a1e0acd19b27b7131362 Author: Michael Meeks <[email protected]> AuthorDate: Thu Apr 4 18:55:07 2019 +0100 Commit: Ashod Nakashian <[email protected]> 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 <[email protected]> Tested-by: Ashod Nakashian <[email protected]> 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 <[email protected]> AuthorDate: Wed Apr 3 21:34:47 2019 +0100 Commit: Ashod Nakashian <[email protected]> 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 <[email protected]> Tested-by: Ashod Nakashian <[email protected]> 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 { _______________________________________________ Libreoffice-commits mailing list [email protected] https://lists.freedesktop.org/mailman/listinfo/libreoffice-commits
