001/*
002 * Copyright (c) 2013, 2014, Oracle and/or its affiliates. All rights reserved.
003 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
004 *
005 * This code is free software; you can redistribute it and/or modify it
006 * under the terms of the GNU General Public License version 2 only, as
007 * published by the Free Software Foundation.
008 *
009 * This code is distributed in the hope that it will be useful, but WITHOUT
010 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
011 * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
012 * version 2 for more details (a copy is included in the LICENSE file that
013 * accompanied this code).
014 *
015 * You should have received a copy of the GNU General Public License version
016 * 2 along with this work; if not, write to the Free Software Foundation,
017 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
018 *
019 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
020 * or visit www.oracle.com if you need additional information or have any
021 * questions.
022 */
023package com.oracle.graal.hotspot.debug;
024
025import java.io.*;
026import java.util.*;
027import java.util.Map.Entry;
028import java.util.concurrent.*;
029import java.util.concurrent.atomic.*;
030
031import jdk.internal.jvmci.common.*;
032import jdk.internal.jvmci.hotspot.*;
033import jdk.internal.jvmci.options.*;
034
035import com.oracle.graal.debug.*;
036import com.oracle.graal.hotspot.replacements.*;
037import com.oracle.graal.nodes.debug.*;
038
039//JaCoCo Exclude
040
041/**
042 * This class contains infrastructure to maintain counters based on {@link DynamicCounterNode}s. The
043 * infrastructure is enabled by specifying either the GenericDynamicCounters or
044 * BenchmarkDynamicCounters option.
045 * <p>
046 *
047 * The counters are kept in a special area allocated for each native JavaThread object, and the
048 * number of counters is configured using {@code -XX:GraalCounterSize=value}.
049 * {@code -XX:+/-GraalCountersExcludeCompiler} configures whether to exclude compiler threads
050 * (defaults to true).
051 *
052 * The subsystems that use the logging need to have their own options to turn on the counters, and
053 * insert DynamicCounterNodes when they're enabled.
054 *
055 * Counters will be displayed as a rate (per second) if their group name starts with "~", otherwise
056 * they will be displayed as a total number.
057 *
058 * <h1>Example</h1> In order to create statistics about allocations within the DaCapo pmd benchmark
059 * the following steps are necessary:
060 * <ul>
061 * <li>Set {@code -XX:GraalCounterSize=value}. The actual required value depends on the granularity
062 * of the profiling, 10000 should be enough for most cases.</li>
063 * <li>Also: {@code -XX:+/-GraalCountersExcludeCompiler} specifies whether the numbers generated by
064 * compiler threads should be excluded (default: true).</li>
065 * <li>Start the DaCapo pmd benchmark with
066 * {@code "-G:BenchmarkDynamicCounters=err, starting ====, PASSED in "} and
067 * {@code -G:+ProfileAllocations}.</li>
068 * <li>The numbers will only include allocation from compiled code!</li>
069 * <li>The counters can be further configured by modifying the
070 * {@link NewObjectSnippets#PROFILE_MODE} field.</li>
071 * </ul>
072 */
073public class BenchmarkCounters {
074
075    static class Options {
076
077        //@formatter:off
078        @Option(help = "Turn on the benchmark counters, and displays the results on VM shutdown", type = OptionType.Debug)
079        private static final OptionValue<Boolean> GenericDynamicCounters = new OptionValue<>(false);
080        @Option(help = "Turn on the benchmark counters, and displays the results every n milliseconds", type = OptionType.Debug)
081        private static final OptionValue<Integer> TimedDynamicCounters = new OptionValue<>(-1);
082
083        @Option(help = "Turn on the benchmark counters, and listen for specific patterns on System.out/System.err:%n" +
084                       "Format: (err|out),start pattern,end pattern (~ matches multiple digits)%n" +
085                       "Examples:%n" +
086                       "  dacapo = 'err, starting =====, PASSED in'%n" +
087                       "  specjvm2008 = 'out,Iteration ~ (~s) begins:,Iteration ~ (~s) ends:'", type = OptionType.Debug)
088        private static final OptionValue<String> BenchmarkDynamicCounters = new OptionValue<>(null);
089        @Option(help = "Use grouping separators for number printing", type = OptionType.Debug)
090        private static final OptionValue<Boolean> DynamicCountersPrintGroupSeparator = new OptionValue<>(true);
091        @Option(help = "Print in human readable format", type = OptionType.Debug)
092        private static final OptionValue<Boolean> DynamicCountersHumanReadable = new OptionValue<>(true);
093        //@formatter:on
094    }
095
096    private static final boolean DUMP_STATIC = false;
097
098    public static boolean enabled = false;
099
100    private static class Counter {
101        public final int index;
102        public final String group;
103        public final AtomicLong staticCounters;
104
105        public Counter(int index, String group, AtomicLong staticCounters) {
106            this.index = index;
107            this.group = group;
108            this.staticCounters = staticCounters;
109        }
110    }
111
112    public static final ConcurrentHashMap<String, Counter> counterMap = new ConcurrentHashMap<>();
113    public static long[] delta;
114
115    public static int getIndexConstantIncrement(String name, String group, HotSpotVMConfig config, long increment) {
116        Counter counter = getCounter(name, group, config);
117        counter.staticCounters.addAndGet(increment);
118        return counter.index;
119    }
120
121    public static int getIndex(String name, String group, HotSpotVMConfig config) {
122        Counter counter = getCounter(name, group, config);
123        return counter.index;
124    }
125
126    @SuppressFBWarnings(value = "AT_OPERATION_SEQUENCE_ON_CONCURRENT_ABSTRACTION", justification = "concurrent abstraction calls are in synchronized block")
127    private static Counter getCounter(String name, String group, HotSpotVMConfig config) throws JVMCIError {
128        if (!enabled) {
129            throw new JVMCIError("cannot access count index when counters are not enabled: " + group + ", " + name);
130        }
131        String nameGroup = name + "#" + group;
132        Counter counter = counterMap.get(nameGroup);
133        if (counter == null) {
134            synchronized (BenchmarkCounters.class) {
135                counter = counterMap.get(nameGroup);
136                if (counter == null) {
137                    counter = new Counter(counterMap.size(), group, new AtomicLong());
138                    counterMap.put(nameGroup, counter);
139                }
140            }
141        }
142        assert counter.group.equals(group) : "mismatching groups: " + counter.group + " vs. " + group;
143        int countersSize = config.jvmciCountersSize;
144        if (counter.index >= countersSize) {
145            throw new JVMCIError("too many counters, reduce number of counters or increase -XX:GraalCounterSize=... (current value: " + countersSize + ")");
146        }
147        return counter;
148    }
149
150    private static synchronized void dump(PrintStream out, double seconds, long[] counters, int maxRows) {
151        if (!counterMap.isEmpty()) {
152            out.println("====== dynamic counters (" + counterMap.size() + " in total) ======");
153            TreeSet<String> set = new TreeSet<>();
154            counterMap.forEach((nameGroup, counter) -> set.add(counter.group));
155            for (String group : set) {
156                if (group != null) {
157                    if (DUMP_STATIC) {
158                        dumpCounters(out, seconds, counters, true, group, maxRows);
159                    }
160                    dumpCounters(out, seconds, counters, false, group, maxRows);
161                }
162            }
163            out.println("============================");
164
165            clear(counters);
166        }
167    }
168
169    private static synchronized void clear(long[] counters) {
170        delta = counters;
171    }
172
173    private static synchronized void dumpCounters(PrintStream out, double seconds, long[] counters, boolean staticCounter, String group, int maxRows) {
174
175        // collect the numbers
176        long[] array;
177        if (staticCounter) {
178            array = new long[counterMap.size()];
179            for (Counter counter : counterMap.values()) {
180                array[counter.index] = counter.staticCounters.get();
181            }
182        } else {
183            array = counters.clone();
184            for (int i = 0; i < array.length; i++) {
185                array[i] -= delta[i];
186            }
187        }
188        Set<Entry<String, Counter>> counterEntrySet = counterMap.entrySet();
189        if (Options.DynamicCountersHumanReadable.getValue()) {
190            dumpHumanReadable(out, seconds, staticCounter, group, maxRows, array, counterEntrySet);
191        } else {
192            dumpComputerReadable(out, staticCounter, group, array, counterEntrySet);
193        }
194    }
195
196    private static String getName(String nameGroup, String group) {
197        return nameGroup.substring(0, nameGroup.length() - group.length() - 1);
198    }
199
200    private static void dumpHumanReadable(PrintStream out, double seconds, boolean staticCounter, String group, int maxRows, long[] array, Set<Entry<String, Counter>> counterEntrySet) {
201        // sort the counters by putting them into a sorted map
202        TreeMap<Long, String> sorted = new TreeMap<>();
203        long sum = 0;
204        for (Map.Entry<String, Counter> entry : counterEntrySet) {
205            Counter counter = entry.getValue();
206            int index = counter.index;
207            if (counter.group.equals(group)) {
208                sum += array[index];
209                sorted.put(array[index] * array.length + index, getName(entry.getKey(), group));
210            }
211        }
212
213        if (sum > 0) {
214            long cutoff = sorted.size() < 10 ? 1 : Math.max(1, sum / 100);
215            int cnt = sorted.size();
216
217            // remove everything below cutoff and keep at most maxRows
218            Iterator<Map.Entry<Long, String>> iter = sorted.entrySet().iterator();
219            while (iter.hasNext()) {
220                Map.Entry<Long, String> entry = iter.next();
221                long counter = entry.getKey() / array.length;
222                if (counter < cutoff || cnt > maxRows) {
223                    iter.remove();
224                }
225                cnt--;
226            }
227
228            String numFmt = Options.DynamicCountersPrintGroupSeparator.getValue() ? "%,19d" : "%19d";
229            if (staticCounter) {
230                out.println("=========== " + group + " (static counters):");
231                for (Map.Entry<Long, String> entry : sorted.entrySet()) {
232                    long counter = entry.getKey() / array.length;
233                    out.format(Locale.US, numFmt + " %3d%%  %s\n", counter, percentage(counter, sum), entry.getValue());
234                }
235                out.format(Locale.US, numFmt + " total\n", sum);
236            } else {
237                if (group.startsWith("~")) {
238                    out.println("=========== " + group + " (dynamic counters), time = " + seconds + " s:");
239                    for (Map.Entry<Long, String> entry : sorted.entrySet()) {
240                        long counter = entry.getKey() / array.length;
241                        out.format(Locale.US, numFmt + "/s %3d%%  %s\n", (long) (counter / seconds), percentage(counter, sum), entry.getValue());
242                    }
243                    out.format(Locale.US, numFmt + "/s total\n", (long) (sum / seconds));
244                } else {
245                    out.println("=========== " + group + " (dynamic counters):");
246                    for (Map.Entry<Long, String> entry : sorted.entrySet()) {
247                        long counter = entry.getKey() / array.length;
248                        out.format(Locale.US, numFmt + " %3d%%  %s\n", counter, percentage(counter, sum), entry.getValue());
249                    }
250                    out.format(Locale.US, numFmt + " total\n", sum);
251                }
252            }
253        }
254    }
255
256    private static void dumpComputerReadable(PrintStream out, boolean staticCounter, String group, long[] array, Set<Entry<String, Counter>> counterEntrySet) {
257        String category = staticCounter ? "static counters" : "dynamic counters";
258        for (Map.Entry<String, Counter> entry : counterEntrySet) {
259            Counter counter = entry.getValue();
260            if (counter.group.equals(group)) {
261                String name = getName(entry.getKey(), group);
262                int index = counter.index;
263                long value = array[index];
264                // TODO(je): escape strings
265                out.printf("%s;%s;%s;%d\n", category, group, name, value);
266            }
267        }
268    }
269
270    private static long percentage(long counter, long sum) {
271        return (counter * 200 + 1) / sum / 2;
272    }
273
274    private abstract static class CallbackOutputStream extends OutputStream {
275
276        protected final PrintStream delegate;
277        private final byte[][] patterns;
278        private final int[] positions;
279
280        public CallbackOutputStream(PrintStream delegate, String... patterns) {
281            this.delegate = delegate;
282            this.positions = new int[patterns.length];
283            this.patterns = new byte[patterns.length][];
284            for (int i = 0; i < patterns.length; i++) {
285                this.patterns[i] = patterns[i].getBytes();
286            }
287        }
288
289        protected abstract void patternFound(int index);
290
291        @Override
292        public void write(int b) throws IOException {
293            try {
294                delegate.write(b);
295                for (int i = 0; i < patterns.length; i++) {
296                    int j = positions[i];
297                    byte[] cs = patterns[i];
298                    byte patternChar = cs[j];
299                    if (patternChar == '~' && Character.isDigit(b)) {
300                        // nothing to do...
301                    } else {
302                        if (patternChar == '~') {
303                            patternChar = cs[++positions[i]];
304                        }
305                        if (b == patternChar) {
306                            positions[i]++;
307                        } else {
308                            positions[i] = 0;
309                        }
310                    }
311                    if (positions[i] == patterns[i].length) {
312                        positions[i] = 0;
313                        patternFound(i);
314                    }
315                }
316            } catch (RuntimeException e) {
317                e.printStackTrace(delegate);
318                throw e;
319            }
320        }
321    }
322
323    public static void initialize(final CompilerToVM compilerToVM) {
324        final class BenchmarkCountersOutputStream extends CallbackOutputStream {
325
326            private long startTime;
327            private boolean running;
328            private boolean waitingForEnd;
329
330            private BenchmarkCountersOutputStream(PrintStream delegate, String start, String end) {
331                super(delegate, new String[]{"\n", end, start});
332            }
333
334            @Override
335            protected void patternFound(int index) {
336                switch (index) {
337                    case 2:
338                        startTime = System.nanoTime();
339                        BenchmarkCounters.clear(compilerToVM.collectCounters());
340                        running = true;
341                        break;
342                    case 1:
343                        if (running) {
344                            waitingForEnd = true;
345                        }
346                        break;
347                    case 0:
348                        if (waitingForEnd) {
349                            waitingForEnd = false;
350                            running = false;
351                            BenchmarkCounters.dump(delegate, (System.nanoTime() - startTime) / 1000000000d, compilerToVM.collectCounters(), 100);
352                        }
353                        break;
354                }
355            }
356        }
357
358        if (Options.BenchmarkDynamicCounters.getValue() != null) {
359            String[] arguments = Options.BenchmarkDynamicCounters.getValue().split(",");
360            if (arguments.length == 0 || (arguments.length % 3) != 0) {
361                throw new JVMCIError("invalid arguments to BenchmarkDynamicCounters: (err|out),start,end,(err|out),start,end,... (~ matches multiple digits)");
362            }
363            for (int i = 0; i < arguments.length; i += 3) {
364                if (arguments[i].equals("err")) {
365                    System.setErr(new PrintStream(new BenchmarkCountersOutputStream(System.err, arguments[i + 1], arguments[i + 2])));
366                } else if (arguments[i].equals("out")) {
367                    System.setOut(new PrintStream(new BenchmarkCountersOutputStream(System.out, arguments[i + 1], arguments[i + 2])));
368                } else {
369                    throw new JVMCIError("invalid arguments to BenchmarkDynamicCounters: err|out");
370                }
371            }
372            enabled = true;
373        }
374        if (Options.GenericDynamicCounters.getValue()) {
375            enabled = true;
376        }
377        if (Options.TimedDynamicCounters.getValue() > 0) {
378            Thread thread = new Thread() {
379                long lastTime = System.nanoTime();
380                PrintStream out = TTY.out;
381
382                @Override
383                public void run() {
384                    while (true) {
385                        try {
386                            Thread.sleep(Options.TimedDynamicCounters.getValue());
387                        } catch (InterruptedException e) {
388                        }
389                        long time = System.nanoTime();
390                        dump(out, (time - lastTime) / 1000000000d, compilerToVM.collectCounters(), 10);
391                        lastTime = time;
392                    }
393                }
394            };
395            thread.setDaemon(true);
396            thread.setPriority(Thread.MAX_PRIORITY);
397            thread.start();
398            enabled = true;
399        }
400        if (enabled) {
401            clear(compilerToVM.collectCounters());
402        }
403    }
404
405    public static void shutdown(CompilerToVM compilerToVM, long compilerStartTime) {
406        if (Options.GenericDynamicCounters.getValue()) {
407            dump(TTY.out, (System.nanoTime() - compilerStartTime) / 1000000000d, compilerToVM.collectCounters(), 100);
408        }
409    }
410}