changeset 830:98f49f0c2ecd

profilers: linux-perf rebuild, properly handle the absence of assembly/perf-output, selectable merge and printing windows, selectable events to gather, account the events outside generated code.
author shade
date Thu, 26 Jun 2014 12:27:22 +0400
parents 9b0fae2b911c
children 93e71a175d41
files jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfAsmProfiler.java
diffstat 1 files changed, 400 insertions(+), 136 deletions(-) [+]
line wrap: on
line diff
--- a/jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfAsmProfiler.java	Wed Jun 25 19:29:35 2014 +0400
+++ b/jmh-core/src/main/java/org/openjdk/jmh/profile/LinuxPerfAsmProfiler.java	Thu Jun 26 12:27:22 2014 +0400
@@ -30,6 +30,7 @@
 import org.openjdk.jmh.results.Result;
 import org.openjdk.jmh.results.ResultRole;
 import org.openjdk.jmh.util.FileUtils;
+import org.openjdk.jmh.util.HashMultiset;
 import org.openjdk.jmh.util.InputStreamDrainer;
 import org.openjdk.jmh.util.Multiset;
 import org.openjdk.jmh.util.TreeMultiset;
@@ -45,19 +46,36 @@
 import java.io.InputStreamReader;
 import java.io.PrintWriter;
 import java.io.StringWriter;
-import java.util.ArrayDeque;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collection;
 import java.util.Collections;
+import java.util.Comparator;
 import java.util.HashMap;
+import java.util.Iterator;
+import java.util.LinkedHashMap;
+import java.util.List;
 import java.util.Map;
+import java.util.Set;
+import java.util.SortedMap;
+import java.util.SortedSet;
 import java.util.TreeMap;
+import java.util.TreeSet;
 import java.util.concurrent.TimeUnit;
 
 public class LinuxPerfAsmProfiler implements ExternalProfiler {
-    private static final String[] EVENTS = {"cycles", "instructions"};
-    private static final String[] EVENTS_SHORT = {"clk", "insn"};
+
+    /** Events to gather **/
+    private static final String[] EVENTS = System.getProperty("jmh.perfasm.events", "cycles,instructions").split(",");
+
+    /** Cutoff threshold for hot region: the regions with event count over threshold would be shown */
+    private static final double THRESHOLD_RATE = Double.valueOf(System.getProperty("jmh.perfasm.hotThreshold", "0.10"));
+
+    /** Print margin: how many "context" lines without counters to show in each region */
+    private static final int PRINT_MARGIN = Integer.getInteger("jmh.perfasm.printMargin", 10);
+
+    /** Merge margin: the regions separated by less than the margin are considered the same */
+    private static final int MERGE_MARGIN = Integer.getInteger("jmh.perfasm.mergeMargin", 32);
 
     private String perfBinData;
     private String perfParsedData;
@@ -157,9 +175,6 @@
          * 1. Call perf to produce the machine-readable data.
          */
 
-        StringWriter sw = new StringWriter();
-        PrintWriter pw = new PrintWriter(sw);
-
         try {
             Process p = Runtime.getRuntime().exec("perf script -i " + perfBinData);
 
@@ -185,149 +200,184 @@
             throw new IllegalStateException(ex);
         }
 
-        try {
+        StringWriter sw = new StringWriter();
+        PrintWriter pw = new PrintWriter(sw);
 
-            /*
-             * 2. Read the perf data
-             */
+        /**
+         * 2. Read out perf output
+         */
 
-            FileInputStream fis = new FileInputStream(perfParsedData);
-            BufferedReader reader = new BufferedReader(new InputStreamReader(fis));
+        Map<String, Multiset<Long>> events = readEvents();
 
-            Map<String, Multiset<Long>> events = new TreeMap<String, Multiset<Long>>();
-            Multiset<Long> eventAddrs = new TreeMultiset<Long>();
+        if (!events.isEmpty()) {
+            pw.println("Perf output processed:");
+            int cnt = 1;
+            for (String event : events.keySet()) {
+                pw.printf(" Column %d: %s (%d total events)%n", cnt, event, events.get(event).size());
+                cnt++;
+            }
+            pw.println();
+        } else {
+            pw.println();
+            pw.println("No perf data, make sure \"perf stat echo\" is indeed working.");
+            pw.println();
+        }
 
-            String line;
-            while ((line = reader.readLine()) != null) {
-                if (line.startsWith("#")) continue;
-                line = line.trim();
-                String[] elements = line.split("[ ]+");
+        /**
+         * 3. Read out PrintAssembly output
+         */
 
-                if (elements[0].equalsIgnoreCase("java")) {
-                    String evName = elements[3].replace(":", "");
-                    Multiset<Long> evs = events.get(evName);
-                    if (evs == null) {
-                        evs = new TreeMultiset<Long>();
-                        events.put(evName, evs);
-                    }
-                    try {
-                        Long element = Long.valueOf(elements[4], 16);
-                        evs.add(element);
-                        eventAddrs.add(element);
-                    } catch (NumberFormatException e) {
-                        // should it be kernel code?
-                    }
+        Assembly assembly = readAssembly(stdOut);
+        if (!assembly.isEmpty()) {
+            pw.printf("PrintAssembly processed: %d total lines%n", assembly.size());
+        } else {
+            pw.println();
+            pw.println("No assembly, make sure your JDK is PrintAssembly-enabled:\n    https://wikis.oracle.com/display/HotSpotInternals/PrintAssembly");
+            pw.println();
+        }
+
+        /**
+         * 4. Figure out generated code regions
+         */
+
+        Collection<Region> regions = makeRegions(combine(events), assembly, events);
+
+        /**
+         * 5. Figure out interesting regions, and print them out
+         */
+
+        Map<String, Long> totalCounts = new HashMap<String, Long>();
+        for (String event : events.keySet()) {
+            totalCounts.put(event, (long) events.get(event).size());
+        }
+
+        SortedSet<Region> interestingRegions = new TreeSet<Region>(Region.BEGIN_COMPARATOR);
+        for (String event : events.keySet()) {
+            TreeSet<Region> topRegions = new TreeSet<Region>(Region.getSortedEventComparator(event));
+            topRegions.addAll(regions);
+
+            long threshold = (long) (THRESHOLD_RATE * totalCounts.get(event));
+            for (Region r : topRegions) {
+                if (r.getEventCount(event) > threshold) {
+                    interestingRegions.add(r);
                 }
             }
+        }
 
-            /*
-             * 3. Compute threshold cutoff for events.
-             */
+        Multiset<String> accounted = new HashMultiset<String>();
+        if (!interestingRegions.isEmpty()) {
+            pw.println();
+            pw.printf("Hottest regions in generated code (>%.2f%% events):%n", THRESHOLD_RATE * 100);
 
-            final int CONTEXT_BUFFER = 10;
-            final double FILTER_THRESHOLD = 0.001;
+            int cnt = 1;
+            for (Region r : interestingRegions) {
+                printDottedLine(pw, "Region " + cnt);
+                for (ASMLine line : r.code) {
+                    for (String event : r.events.keySet()) {
+                        int count = (line.addr != null) ? r.events.get(event).count(line.addr) : 0;
+                        if (count > 0) {
+                            pw.printf("%6.2f%%  ", 100.0 * count / totalCounts.get(event));
+                        } else {
+                            pw.printf("%9s", "");
+                        }
+                    }
+                    pw.println(line.code);
+                }
 
-            long sum = 0L;
-            for (long a : eventAddrs.keys()) {
-                sum += eventAddrs.count(a);
+                printDottedLine(pw, null);
+                for (String event : r.events.keySet()) {
+                    int count = r.events.get(event).size();
+                    if (count > 0) {
+                        pw.printf("%6.2f%%  ", 100.0 * count / totalCounts.get(event));
+                    } else {
+                        pw.printf("%9s", "");
+                    }
+                    accounted.add(event, count);
+                }
+                pw.println("<total for region " + cnt + ">");
+                pw.println();
+                cnt++;
+            }
+        }
+
+        /**
+         * 6. Print out all residuals
+         */
+
+        printDottedLine(pw, "Other generated code");
+        Multiset<String> allRegions = new HashMultiset<String>();
+        for (Region r : regions) {
+            for (String event : r.events.keySet()) {
+                int count = r.events.get(event).size();
+                allRegions.add(event, count);
+            }
+        }
+
+        for (String event : totalCounts.keySet()) {
+            long count = allRegions.count(event) - accounted.count(event);
+            if (count > 0) {
+                pw.printf("%6.2f%%  ", 100.0 * count / totalCounts.get(event));
+            } else {
+                pw.printf("%9s", "");
+            }
+        }
+        pw.println("<unknown>");
+        pw.println();
+
+
+        printDottedLine(pw, "Other non-generated code");
+        for (String event : totalCounts.keySet()) {
+            long count = totalCounts.get(event) - allRegions.count(event);
+            if (count > 0) {
+                pw.printf("%6.2f%%  ", 100.0 * count / totalCounts.get(event));
+            } else {
+                pw.printf("%9s", "");
+            }
+        }
+        pw.println("<unknown>");
+        pw.println();
+
+        return new PerfResult(sw.toString());
+    }
+
+    void printDottedLine(PrintWriter pw, String header) {
+        final int HEADER_WIDTH = 80;
+
+        pw.print("....");
+        if (header != null) {
+            header = "[" + header + "]";
+            pw.print(header);
+        } else {
+            header = "";
+        }
+
+        for (int c = 0; c < HEADER_WIDTH - 4 - header.length(); c++) {
+            pw.print(".");
+        }
+        pw.println();
+    }
+
+    Collection<Region> makeRegions(Set<AddrInterval> intervals, Assembly asms, Map<String, Multiset<Long>> events) {
+        SortedSet<Region> regions = new TreeSet<Region>(Region.BEGIN_COMPARATOR);
+
+        for (AddrInterval interval : intervals) {
+            List<ASMLine> regionLines = asms.getLines(interval.begin, interval.end, PRINT_MARGIN);
+
+            Map<String, Multiset<Long>> eventsByAddr = new LinkedHashMap<String, Multiset<Long>>();
+            for (String event : events.keySet()) {
+                HashMultiset<Long> r = new HashMultiset<Long>();
+                for (ASMLine line : regionLines) {
+                    if (line.addr == null) continue;
+                    int count = events.get(event).count(line.addr);
+                    r.add(line.addr, count);
+                }
+                eventsByAddr.put(event, r);
             }
 
-            final int THRESHOLD = (int) (sum * FILTER_THRESHOLD);
+            regions.add(new Region(interval.begin, interval.end, regionLines, eventsByAddr));
+        }
 
-            /*
-             * 4. Read the disassembly and selectively print the hottest blocks:
-             */
-
-            ArrayDeque<String> buffer = new ArrayDeque<String>(CONTEXT_BUFFER);
-
-            int linesToPrint = 0;
-
-            Map<String, Integer> sizes = new HashMap<String, Integer>();
-            for (String eventType : EVENTS) {
-                sizes.put(eventType, events.get(eventType).size());
-            }
-
-            BufferedReader br = new BufferedReader(new FileReader(stdOut));
-            while ((line = br.readLine()) != null) {
-                if (line.trim().isEmpty()) continue;
-
-                String[] elements = line.trim().split(" ");
-
-                String bufferedLine = "";
-
-                boolean eventsPrinted = false;
-                if (elements.length >= 1) {
-                    try {
-                        Long addr = Long.valueOf(elements[0].replace("0x", "").replace(":", ""), 16);
-                        int eventCount = eventAddrs.count(addr);
-
-                        if (eventCount > 0) {
-                            for (String eventType : EVENTS) {
-                                int count = events.get(eventType).count(addr);
-                                bufferedLine += String.format("%5.2f%% ", 100.0 * count / sizes.get(eventType));
-                            }
-                            eventsPrinted = true;
-                        }
-
-                        if (eventCount > THRESHOLD)  {
-                            for (String bl : buffer) {
-                                pw.println(bl);
-                            }
-                            buffer.clear();
-                            linesToPrint = CONTEXT_BUFFER;
-                        }
-                    } catch (NumberFormatException e) {
-                        // skip
-                    }
-                }
-
-                if (!eventsPrinted) {
-                    for (String eventType : EVENTS) {
-                        bufferedLine += String.format("%6s ", "");
-                    }
-                }
-
-                bufferedLine += line;
-
-                linesToPrint--;
-                if (linesToPrint >= 0) {
-                    pw.println(bufferedLine);
-                    if (linesToPrint == 0) {
-                        pw.println("---------------------------------------------------------------------------------");
-                        for (String eventType : EVENTS_SHORT) {
-                            pw.print(String.format("%6s ", eventType));
-                        }
-                        pw.println();
-                        pw.println();
-                    }
-                } else {
-                    buffer.add(bufferedLine);
-                    if (buffer.size() > CONTEXT_BUFFER) {
-                        buffer.pollFirst();
-                    }
-                }
-            }
-            pw.println();
-
-            String hot = sw.toString();
-            if (hot.trim().isEmpty()) {
-                return new PerfResult("No assembly, make sure your JDK is PrintAssembly-enabled:\n    https://wikis.oracle.com/display/HotSpotInternals/PrintAssembly");
-            } else {
-                String header = "Hottest generated code regions:\n";
-                header += "(values do not normally add up to 100%, the remaining parts are dispersed\n";
-                header += " across other warm generated code blocks, and VM native code itself; use\n";
-                header += " full-fledged profilers to get a cleaner picture)\n";
-                header += "---------------------------------------------------------------------------------\n";
-                for (String eventType : EVENTS_SHORT) {
-                    header += String.format("%6s ", eventType);
-                }
-                header += "\n";
-                hot = header + hot;
-                return new PerfResult(hot);
-            }
-        } catch (IOException e) {
-            throw new IllegalStateException(e);
-        }
+        return regions;
     }
 
     static class PerfResult extends Result<PerfResult> {
@@ -370,4 +420,218 @@
         }
     }
 
+    static class Assembly {
+        List<ASMLine> lines;
+        SortedMap<Long, Integer> addressMap;
+
+        public Assembly(List<ASMLine> lines, SortedMap<Long, Integer> addressMap) {
+            this.lines = lines;
+            this.addressMap = addressMap;
+        }
+
+        public boolean isEmpty() {
+            return lines.isEmpty();
+        }
+
+        public int size() {
+            return lines.size();
+        }
+
+        public List<ASMLine> getLines(long begin, long end, int window) {
+            SortedMap<Long, Integer> tailMap = addressMap.tailMap(begin);
+
+            Long beginAddr;
+            Integer beginIdx;
+            if (!tailMap.isEmpty()) {
+                beginAddr = tailMap.firstKey();
+                beginIdx = addressMap.get(beginAddr);
+            } else {
+                return Collections.emptyList();
+            }
+
+            SortedMap<Long, Integer> headMap = addressMap.headMap(end);
+
+            Long endAddr;
+            Integer endIdx;
+            if (!headMap.isEmpty()) {
+                endAddr = headMap.lastKey();
+                endIdx = addressMap.get(endAddr);
+            } else {
+                return Collections.emptyList();
+            }
+
+            beginIdx = Math.max(0, beginIdx - window);
+            endIdx = Math.min(lines.size(), endIdx + 2 + window);
+
+            // Compensate for minute discrepancies
+            if (beginIdx < endIdx) {
+                return lines.subList(beginIdx, endIdx);
+            } else {
+                return Collections.emptyList();
+            }
+        }
+    }
+
+    Assembly readAssembly(File stdOut) {
+        try {
+            List<ASMLine> lines = new ArrayList<ASMLine>();
+            SortedMap<Long, Integer> addressMap = new TreeMap<Long, Integer>();
+            String line;
+            BufferedReader br = new BufferedReader(new FileReader(stdOut));
+            while ((line = br.readLine()) != null) {
+                if (line.trim().isEmpty()) continue;
+                String[] elements = line.trim().split(" ");
+
+                if (elements.length >= 1) {
+                    // Seems to be assembly line
+                    try {
+                        Long addr = Long.valueOf(elements[0].replace("0x", "").replace(":", ""), 16);
+                        int idx = lines.size();
+                        lines.add(new ASMLine(addr, line));
+                        addressMap.put(addr, idx);
+                    } catch (NumberFormatException e) {
+                        lines.add(new ASMLine(line));
+                    }
+                } else {
+                    lines.add(new ASMLine(line));
+                }
+            }
+            return new Assembly(lines, addressMap);
+        } catch (IOException e) {
+            return new Assembly(new ArrayList<ASMLine>(), new TreeMap<Long, Integer>());
+        }
+    }
+
+    Map<String, Multiset<Long>> readEvents() {
+        try {
+            FileInputStream fis = new FileInputStream(perfParsedData);
+            BufferedReader reader = new BufferedReader(new InputStreamReader(fis));
+
+            Map<String, Multiset<Long>> events = new LinkedHashMap<String, Multiset<Long>>();
+            for (String evName : EVENTS) {
+                events.put(evName, new TreeMultiset<Long>());
+            }
+
+            String line;
+            while ((line = reader.readLine()) != null) {
+                if (line.startsWith("#")) continue;
+                line = line.trim();
+                String[] elements = line.split("[ ]+");
+
+                if (elements[0].equalsIgnoreCase("java")) {
+                    String evName = elements[3].replace(":", "");
+                    Multiset<Long> evs = events.get(evName);
+                    try {
+                        Long element = Long.valueOf(elements[4], 16);
+                        evs.add(element);
+                    } catch (NumberFormatException e) {
+                        // should it be kernel code?
+                    }
+                }
+            }
+
+            for (Iterator<String> iterator = events.keySet().iterator(); iterator.hasNext(); ) {
+                String key = iterator.next();
+                if (events.get(key).isEmpty()) {
+                    iterator.remove();
+                }
+            }
+
+            return events;
+        } catch (IOException e) {
+            return Collections.emptyMap();
+        }
+    }
+
+    Set<AddrInterval> combine(Map<String, Multiset<Long>> events) {
+        SortedSet<AddrInterval> intervals = new TreeSet<AddrInterval>(new Comparator<AddrInterval>() {
+            @Override
+            public int compare(AddrInterval o1, AddrInterval o2) {
+                return Long.valueOf(o1.begin).compareTo(o2.begin);
+            }
+        });
+
+        SortedSet<Long> addrs = new TreeSet<Long>();
+        for (Map.Entry<String, Multiset<Long>> e : events.entrySet()) {
+            addrs.addAll(e.getValue().keys());
+        }
+
+        Long lastBegin = null;
+        Long lastAddr = null;
+        for (Long addr : addrs) {
+            if (lastAddr == null) {
+                lastAddr = addr;
+                lastBegin = addr;
+            } else {
+                if (addr - lastAddr > MERGE_MARGIN) {
+                    intervals.add(new AddrInterval(lastBegin, lastAddr));
+                    lastBegin = addr;
+                }
+                lastAddr = addr;
+            }
+        }
+
+        return intervals;
+    }
+
+    static class ASMLine {
+        Long addr;
+        String code;
+
+        ASMLine(String code) {
+            this.code = code;
+        }
+
+        ASMLine(long addr, String code) {
+            this.addr = addr;
+            this.code = code;
+        }
+    }
+
+    static class AddrInterval {
+        long begin;
+        long end;
+
+        AddrInterval(long begin, long end) {
+            this.begin = begin;
+            this.end = end;
+        }
+    }
+
+    static class Region {
+        static final Comparator<Region> BEGIN_COMPARATOR = new Comparator<Region>() {
+            @Override
+            public int compare(Region o1, Region o2) {
+                return Long.valueOf(o1.begin).compareTo(o2.begin);
+            }
+        };
+
+        static Comparator<Region> getSortedEventComparator(final String event) {
+            return new Comparator<Region>() {
+                @Override
+                public int compare(Region o1, Region o2) {
+                    return Integer.valueOf(o2.getEventCount(event)).compareTo(o1.getEventCount(event));
+                }
+            };
+        }
+
+        long begin;
+        long end;
+        Collection<ASMLine> code;
+        Map<String, Multiset<Long>> events;
+
+        Region(long begin, long end, Collection<ASMLine> asms, Map<String, Multiset<Long>> events) {
+            this.begin = begin;
+            this.end = end;
+            this.code = asms;
+            this.events = events;
+        }
+
+        int getEventCount(String event) {
+            return events.get(event).size();
+        }
+
+    }
+
 }
+