Publish

1 files changed, 320 insertions, 0 deletions

diff --git a/vespamalloc/bin/parsememorydump.pl b/vespamalloc/bin/parsememorydump.pl
new file mode 100755
index 00000000000..efd3b988aec
--- /dev/null
+++ b/vespamalloc/bin/parsememorydump.pl
@@ -0,0 +1,320 @@
+#!/usr/bin/perl -w
+# Copyright 2016 Yahoo Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+
+# This is a tool to parse the output given by vespamalloc when dumping all
+# memory usage with stacktraces.
+#
+# This tool will try to group similar stack traces together, identify them,
+# and show a report of how much memory you use for various tasks in the given
+# dump.
+#
+# Suggested usage:
+#   - Manually rotate your vespa.log file.
+#   - Send signal to vespamalloc to make it dump stack traces.
+#   - When dump is done, cat all the log files generated in correct order into
+#     one file.
+#   - Send this file to STDIN of this script.
+#
+# By doing it like this, it's easy to rerun this script and to update it to
+# work with anything encountered in your report that this script doesn't
+# currently handle.
+#
+# It is for instance likely, that you need to add some more regexes to match
+# unknown stack traces into appropriate groups.
+
+use strict;
+
+# If this variable is set, unrecognized stack traces will be concatenated to
+# one unrecognized chunk.
+my $combineUnrecognizedStacks = 1;
+# If this variable is set, all stack traces are shown, no matter if they are
+# recognized or not.
+my $showRecognizedStacks = 0;
+# If this variable is set, memory usage is grouped on the first word in the
+# group name. Thus, by using a proper name convention, one can distinguish
+# how much memory are used on various parts of the system
+my $sortOnCategories = 1;
+
+# These patterns are used to recognized what memory is used for based on the
+# stacktrace of the allocation. The keys are regular expressions that can match
+# stacktraces. The value is the group name this allocation will be marked as if
+# the trace matches the regex. If matching multiple entries, the first entry
+# found will be the match.
+
+# Note that as I made this tool to analyze VDS memory usage, the stuff added is
+# just stuff I found using memory in that current run. We should probably add
+# more patterns as needed.
+my %patterns = (
+        
+    'FRT_MemoryTub::BigAlloc.*mbus::MessageBus::send.*' => 'RPC send messagebus message - big alloc',
+    'FRT_MemoryTub::BigAlloc.*storage::rpc::Destination::sendRequest', => 'RPC send storage API command - big alloc',
+    'FRT_RPCRequestPool::AllocRPCRequest.*storage::rpc::Destination::sendRequest' => 'RPC send storage API command',
+
+    'FNET_DataBuffer::Shrink.*FNET_Connection::HandleWriteEvent' => 'RPC shrinked write buffer',
+    'FNET_DataBuffer::Shrink.*FNET_Connection::HandleReadEvent' => 'RPC shrinked read buffer',
+    
+    'FRT_MemoryTub::BigAlloc.*FRT_RPCRequestPacket::Decode.*FNET_Connection::HandleReadEvent' => 'RPC read event - decode - big alloc',
+    'FRT_RPCRequestPool::AllocRPCRequest.*FNET_Connection::HandlePacket.*FNET_Connection::HandleReadEvent' => 'RPC read event - handle packet',
+    'FNET_DataBuffer::Pack.*FNET_Connection::HandleReadEvent' => 'RPC packed read buffer',
+    'FNET_DataBuffer::Pack.*FNET_Connection::HandleWriteEvent' => 'RPC packed write buffer',
+    'FNET_PacketQueue_NoLock::ExpandBuf.*FNET_Connection::HandleWriteEvent()' => 'RPC expand write buffer',
+    'FNET_ChannelPool::AllocChannelCluster.*storage::rpc::Destination::sendRequest' => 'RPC storage API alloc channel cluster',
+    
+    'storage::SlotFileBuffer::getAlignedBuffer.*SlotFileImpl::close' => 'Persistence layer - move buffer to cache',
+    'storage::SlotFileBuffer::getAlignedBuffer.*SlotFileBuffer::getBuffer' => 'Persistence layer - Get aligned buffer',
+    'storage::SlotFileBuffer::getInputBuffer' => 'Persistence layer - Input buffer',
+    'storage::SlotFileBuffer::getIndexBuffer' => 'Persistence layer - Index buffer',
+    'storage::SlotFileBuffer::getOutputBuffer' => 'Persistence layer - Output buffer',
+    'std::vector<storage::SlotFile::WriteEntry.*storage::FileStorThread::onMultiOperation'
+        => 'Persistence layer - Temporary buffer used to store data to write multi operation commands',
+
+    'storage::api::MultiOperationCommand::onDeserialize' => 'Messages - Queued multi operation commands',
+    'storage::api::\S*::makeReply.*storage::MessageDispatcher::handleCommand' => 'Messages - Replies stored in message dispatcher',
+    'document::SerializableArray::onDeserialize.*storage::CommunicationManager::onEvent\(std::auto_ptr<storage::rpc::Event>\)'
+        => 'Messages - Documents from storage API messages - serializable arrays',
+    'document::SerializableDocumentSharedPointer.*storage::rpc::Handle::onEvent\(std::auto_ptr<storage::rpc::Event>\)'
+        => 'Messages - Documents from storage API messages - original byte buffers',
+    'storage::api::StorageMessageAddress::create.*storage::rpc::Handle::onEvent\(std::auto_ptr<storage::rpc::Event>\)'
+        => 'Messages - Storage API message addresses',
+    'document::IdString::createIdString.*storage::api::StorageMessage::onDeserialize'
+        => 'Messages - Document identifiers',
+    'storage::api::ApplyBucketDiffCommand::Entry::Entry.*storage::FileStorThread::run'
+        => 'Messages - Merge apply entries',
+    'storage::api::ApplyBucketDiffCommand::Entry::Entry.*storage::api::StorageMessage::onDeserialize'
+        => 'Messages - Merge apply entries',
+    'storage::api::MultiOperationCommand::MultiOperationCommand.*storage::api::MultiOperationCommand::clone.*storage::MessageDispatcher::handleCommand'
+        => 'Messages - Queued multi operation commands - cloned for local use in message dispatcher',
+
+    'storage::BufHolder::reserve.*storage::FileStorThread::onGetIterCommand' => 'Visiting - Downsized docblocks',
+    'storage::BufHolder::resize.*storage::FileStorThread::onGetIterCommand' => 'Visiting - Upsized docblocks',
+    'documentapi::MultiOperationMessage::MultiOperationMessage.*storage::VisitorManager::send'
+        => 'Visiting - Pending messagebus multi operation messages',
+
+    'JudyLIns.*storage::StorBucketDatabase::(get|insert)' => 'Bucket database - Judy',
+    'JudyLDel.*WrappedEntry::remove' => 'Bucket database - Judy',
+    'std::vector<.*storage::LockableMap.*::WrappedEntry::remove()' => 'Bucket database - Lockable map lock list',
+
+    'document::Printable::toString'
+        => 'Other - Temporary data created during toString operations',
+
+    'metrics::MetricsManager::getSnapshotForConsumer' => 'Metrics - Snapshot created',
+    'storage::BucketManagerMetrics::BucketManagerMetrics\(\)' => 'Metrics - Stored metrics',
+    'storage::FileStorThreadMetrics::FileStorThreadMetrics\(std::basic_string' => 'Metrics - Stored metrics',
+    'metrics::MetricsSet::addAll' => 'Metrics - Add all',
+    'storage::StatusMetricConsumer::run\(\)' => 'Metrics',
+
+    'slobrok::api::MirrorAPI::PerformTask\(\)' => 'Slobrok - Mirror API perform task'
+
+);
+
+my $signal;
+my $starttime;
+my $size;
+my %vals;
+my %counts;
+
+my $mallocfault;
+my $local = 0;
+my $global = 0;
+my $globwaste = 0;
+
+# Go through all the input gotten on STDIN.
+foreach (<>) {
+    if (/^(\d+)\.\d+\s+\S+\s+\d+\s+\S+\s+\S+\s+warning\s+(.*)$/) {
+        # We only care for warnings to logs printed by vespamalloc
+        my ($time, $line) = ($1, $2);
+        if ($line =~ /SignalHandler (\d+) caught/) {
+            # If a dump is just starting, reset all the variables that keeps
+            # state
+            $signal = $1;
+            $size = 0;
+            %vals = ();
+            %counts = ();
+            $local = 0;
+            $global = 0;
+            $globwaste = 0;
+            $mallocfault = undef;
+            $starttime = $time;
+            print "\nProcessing dump from " . localtime($starttime) . "\n";
+        } elsif ($line =~ /^SignalHandler $signal done/) {
+            # If we are at the end of the vespamalloc report, print a report of
+            # what we have found.
+            &printReport();            
+            $starttime = undef;
+        } elsif (!$starttime) {
+            # Ignore output that is not within dump
+        } elsif ($line =~ /^SC\s*\d+\(\s*(\d+)\)\s*GetAlloc\(\s*(\d+)\)\s*GetFree\(\s*\d+\)\s*ExChangeAlloc\(\s*(\d+)\)\s*ExChangeFree\(\s*(\d+)\)\s*ExactAlloc\(\s*(\d+)\)\s*Returned\(\s*(\d+)\)\s*Malloc\(\s*(\d+)\)\s*/) {
+            # Track size groups allocated in hopes of figuring out how much data
+            # waste there is in vespa malloc
+            my ($size, $get, $exalloc, $exfree, $exact, $returned, $malloc) = ($1, $2, $3, $4, $5, $6, $7);
+            #print "$line\n";
+            #print "Size $size, GetAlloc $get, ExChangeAlloc $exalloc, ExChangeFree $exfree, ExactAlloc $exact, Returned $returned, Malloc $malloc\n";
+            my $mult = 65536;
+            if ($size > $mult) { $mult = $size; }
+            my $alloced = $get + $exalloc + $exact;
+            my $ret = $exfree + $returned;
+            if ($size != 2097152) {
+                #print "Adding ($alloced - $ret) * $mult = " . (($alloced - $ret) * $mult) . "\n";
+                my $global = ($alloced - $ret) * $mult;
+                my $waste = $malloc * 1024 * 1024 - ($alloced - $ret) * $mult;
+                #print "Size $size - Global $global - Waste $waste\n";
+                #$global += ($alloced - $ret) * $mult;
+                if ($waste >= 0) {
+                    $global += $global;
+                    $globwaste += $waste;
+                } else {
+                    $mallocfault = 1;
+                }
+            } else {
+                $mallocfault = 1;
+            }
+        } elsif ($line =~ /SC\s*\d+\(\s*(\d+)\)\s*Local\(\s*(\d+)\)/) {
+            # Track size groups allocated in hopes of figuring out how much data
+            # waste there is in vespa malloc
+            
+            #print "Local $1 * $2 = ".($1 * $2)."\n";
+            $local += $1 * $2;
+        } elsif ($line =~ /^SizeClass\s*(\d+)/) {
+            #print "$line\n";
+        } elsif ($line =~ /^(Usage)/) {
+            print "Vespa Malloc $line\n";
+        } elsif ($line =~ /(DataSegment|Free|Start)/) { 
+        } elsif ($line =~ /^(\d+)\s+:\s+\{\s+\S+\s+\S+\s+(\S+[^\}]*)/) {
+            # This should match any stacktrace reported. Add this stacktrace
+            # to the report.
+            my ($count, $value) = ($1, $2);
+            # Unify stack trace
+            $value =~ s/0x[0-9a-f]+//g;
+            $value =~ s/\(\d+\)//g;
+            $value =~ s/\(\)//g;
+            # Remove multiple UNKNOWN lines in backtrace
+            my @stack = split /\s+/, $value;
+            $value = '';
+            my $last = "";
+            foreach (@stack) {
+                my $current = &cppfilt($_);
+                if ($last !~ /UNKNOWN/ || $current !~ /UNKNOWN/) { # Don't print multiple unknown entries after one another
+                    $value .= "\n  " . &cppfilt($_);
+                }
+                $last = $current;
+            }
+            # Detect known stack traces
+            
+            #print "$count - $value\n";
+            my $replaced = 0;
+            foreach my $pat (keys %patterns) {
+                #print "Does $value match $pat?\n";
+                if ($value =~ /$pat/s) {
+                    if ($showRecognizedStacks) {
+                        $value = $patterns{$pat} . $value;
+                    } else {
+                        $value = $patterns{$pat};
+                    }
+                    $replaced = 1;
+                    last;
+                }
+            }
+            if (!$replaced) {
+                if ($combineUnrecognizedStacks) {
+                    $value = "Unrecognized memory allocations";
+                } elsif ($sortOnCategories) {
+                    $value = "Unrecognized memory allocations" . $value;
+                }
+            }
+            if (exists $vals{$value}) {
+                $vals{$value} += $count * $size; 
+                $counts{$value} += $count;
+            } else {
+                $vals{$value} = $count * $size; 
+                $counts{$value} = $count;
+            }
+        } elsif ($line =~ /^Allocated Blocks SC\s*\d+\(\s*(\d+)/) {
+            $size = $1;
+            #print "Size: $1\n";
+        } else {
+            #print "$line\n";
+        }
+    } else {
+        #print "$_";
+    }
+}
+if ($starttime) {
+    print "Input stopped in incomplete trace.\n";
+}
+
+exit(0);
+
+my %filtered;
+
+sub cppfilt {
+    my $val = $_[0];
+    if ($val =~ /UNKNOWN/) {
+        return "UNKNOWN";
+    } elsif (exists $filtered{$val}) {
+        return $filtered{$val};
+    } else {
+        my $result = `c++filt $val`;
+        chomp $result;
+        $filtered{$val} = $result;
+        return $result;
+    }
+}
+
+sub getByteString {
+    my $val = $_[0];
+    if ($val < 5000) {
+        return sprintf("%d B", $val);
+    } elsif ($val < 5000000) {
+        return sprintf("%d kB", $val / 1024);
+    } else {
+        return sprintf("%d MB", $val / (1024 * 1024));
+    }
+}
+
+sub printReport {
+    print "Total vespa malloc unused thread local data: " . &getByteString($local) . "\n";
+    #print "Total global data: $global\n";
+    print "Total vespa malloc global waste data: " . &getByteString($globwaste). "\n";
+
+    my $total = 0;
+    foreach (keys %vals) {
+        $total += $vals{$_};
+    }
+    if (defined $mallocfault) {
+        print "Warning: Some sketchy numbers from vespa malloc, so global and thread local "
+            . "data is probably inaccurate.\n";
+    }
+
+    print "\nSummary of allocated data:\n";
+    print &getByteString($total) . " bytes tracked total\n";
+
+    if ($sortOnCategories) {
+        my %categories;
+        foreach (keys %vals) {
+            if (/^\s*(\S+)/) {
+                my $category = $1;
+                if (exists $categories{$category}) {
+                    ${$categories{$category}}[0] += $vals{$_};
+                    push @{$categories{$category}}, $_;
+                } else {
+                    $categories{$category} = [ $vals{$_}, $_ ];
+                }
+            }
+        }
+        foreach (sort { ${$categories{$b}}[0] <=> ${$categories{$a}}[0] } keys %categories) {
+            my @values = @{ $categories{$_} };
+            print &getByteString($values[0]) . " - $_\n";
+            shift @values;
+            
+            foreach my $val (sort { $vals{$b} <=> $vals{$a} } @values) {
+                my $stack = $val;
+                $stack =~ s/\n/\n    /sg;
+                print "    " . &getByteString($vals{$val}) . " - " . $counts{$val} . " allocations - $stack\n";
+            }
+        }
+    } else {
+        foreach (sort { $vals{$b} <=> $vals{$a} } keys %vals) {
+            print &getByteString($vals{$_}) . " - " . $counts{$_} . " allocations - $_\n";
+        }
+    }
+}