1 /* 2 * Copyright (C) 2010 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 package dalvik.system; 18 19 import java.io.BufferedOutputStream; 20 import java.io.File; 21 import java.io.FileOutputStream; 22 import java.io.IOException; 23 import java.io.PrintStream; 24 import java.util.ArrayList; 25 import java.util.Arrays; 26 import java.util.Collections; 27 import java.util.Comparator; 28 import java.util.Date; 29 import java.util.HashMap; 30 import java.util.HashSet; 31 import java.util.List; 32 import java.util.Map.Entry; 33 import java.util.Map; 34 import java.util.Set; 35 import java.util.Timer; 36 import java.util.TimerTask; 37 38 /** 39 * A sampling profiler. It currently is implemented without any 40 * virtual machine support, relying solely on {@code 41 * Thread.getStackTrace} to collect samples. As such, the overhead is 42 * higher than a native approach and it does not provide insight into 43 * where time is spent within native code, but it can still provide 44 * useful insight into where a program is spending time. 45 * 46 * <h3>Usage Example</h3> 47 * 48 * The following example shows how to use the {@code 49 * SamplingProfiler}. It samples the current thread's stack to a depth 50 * of 12 stack frame elements over two different measurement periods 51 * at a rate of 10 samples a second. In then prints the results in 52 * hprof format to the standard output. 53 * 54 * <pre> {@code 55 * ThreadSet threadSet = SamplingProfiler.newArrayThreadSet(Thread.currentThread()); 56 * SamplingProfiler profiler = new SamplingProfiler(12, threadSet); 57 * profiler.start(10); 58 * // period of measurement 59 * profiler.stop(); 60 * // period of non-measurement 61 * profiler.start(10); 62 * // another period of measurement 63 * profiler.stop(); 64 * profiler.shutdown(); 65 * profiler.writeHprofData(System.out); 66 * }</pre> 67 * 68 * @hide 69 */ 70 public final class SamplingProfiler { 71 72 /* 73 * Real hprof output examples don't start the thread and trace 74 * identifiers at one but seem to start at these arbitrary 75 * constants. It certainly seems useful to have relatively unique 76 * identifers when manual searching hprof output. 77 */ 78 private int nextThreadId = 200001; 79 private int nextTraceId = 300001; 80 private int nextObjectId = 1; 81 82 /** 83 * Map of currently active threads to their identifiers. When 84 * threads disappear they are removed and only referenced by their 85 * identifiers to prevent retaining garbage threads. 86 */ 87 private final Map<Thread, Integer> threadIds = new HashMap<Thread, Integer>(); 88 89 /** 90 * List of thread creation and death events. 91 */ 92 private final List<ThreadEvent> threadHistory = new ArrayList<ThreadEvent>(); 93 94 /** 95 * Map of stack traces to a mutable sample count. 96 */ 97 private final Map<Trace, int[]> traces = new HashMap<Trace, int[]>(); 98 99 /** 100 * Timer that is used for the lifetime of the profiler 101 */ 102 // note that dalvik/vm/Thread.c depends on this name 103 private final Timer timer = new Timer("SamplingProfiler", true); 104 105 /** 106 * A sampler is created every time profiling starts and cleared 107 * everytime profiling stops because once a {@code TimerTask} is 108 * canceled it cannot be reused. 109 */ 110 private TimerTask sampler; 111 112 /** 113 * The maximum number of {@code StackTraceElements} to retain in 114 * each stack. 115 */ 116 private final int depth; 117 118 /** 119 * The {@code ThreadSet} that identifies which threads to sample. 120 */ 121 private final ThreadSet threadSet; 122 123 /** 124 * Create a sampling profiler that collects stacks with the 125 * specified depth from the threads specified by the specified 126 * thread collector. 127 * 128 * @param depth The maximum stack depth to retain for each sample 129 * similar to the hprof option of the same name. Any stack deeper 130 * than this will be truncated to this depth. A good starting 131 * value is 4 although it is not uncommon to need to raise this to 132 * get enough context to understand program behavior. While 133 * programs with extensive recursion may require a high value for 134 * depth, simply passing in a value for Integer.MAX_VALUE is not 135 * advised because of the significant memory need to retain such 136 * stacks and runtime overhead to compare stacks. 137 */ 138 public SamplingProfiler(int depth, ThreadSet threadSet) { 139 this.depth = depth; 140 this.threadSet = threadSet; 141 } 142 143 /** 144 * A ThreadSet specifies the set of threads to sample. 145 */ 146 public static interface ThreadSet { 147 /** 148 * Returns an array containing the threads to be sampled. The 149 * array may be longer than the number of threads to be 150 * sampled, in which case the extra elements must be null. 151 */ 152 public Thread[] threads(); 153 } 154 155 /** 156 * Returns a ThreadSet for a fixed set of threads that will not 157 * vary at runtime. This has less overhead than a dynamically 158 * calculated set, such as {@link newThreadGroupTheadSet}, which has 159 * to enumerate the threads each time profiler wants to collect 160 * samples. 161 */ 162 public static ThreadSet newArrayThreadSet(Thread... threads) { 163 return new ArrayThreadSet(threads); 164 } 165 166 /** 167 * An ArrayThreadSet samples a fixed set of threads that does not 168 * vary over the life of the profiler. 169 */ 170 private static class ArrayThreadSet implements ThreadSet { 171 private final Thread[] threads; 172 public ArrayThreadSet(Thread... threads) { 173 if (threads == null) { 174 throw new NullPointerException("threads == null"); 175 } 176 this.threads = threads; 177 } 178 public Thread[] threads() { 179 return threads; 180 } 181 } 182 183 /** 184 * Returns a ThreadSet that is dynamically computed based on the 185 * threads found in the specified ThreadGroup and that 186 * ThreadGroup's children. 187 */ 188 public static ThreadSet newThreadGroupTheadSet(ThreadGroup threadGroup) { 189 return new ThreadGroupThreadSet(threadGroup); 190 } 191 192 /** 193 * An ThreadGroupThreadSet sample the threads from the specified 194 * ThreadGroup and the ThreadGroup's children 195 */ 196 private static class ThreadGroupThreadSet implements ThreadSet { 197 private final ThreadGroup threadGroup; 198 private Thread[] threads; 199 private int lastThread; 200 201 public ThreadGroupThreadSet(ThreadGroup threadGroup) { 202 if (threadGroup == null) { 203 throw new NullPointerException("threadGroup == null"); 204 } 205 this.threadGroup = threadGroup; 206 resize(); 207 } 208 209 private void resize() { 210 int count = threadGroup.activeCount(); 211 // we can only tell if we had enough room for all active 212 // threads if we actually are larger than the the number of 213 // active threads. making it larger also leaves us room to 214 // tolerate additional threads without resizing. 215 threads = new Thread[count*2]; 216 lastThread = 0; 217 } 218 219 public Thread[] threads() { 220 int threadCount; 221 while (true) { 222 threadCount = threadGroup.enumerate(threads); 223 if (threadCount == threads.length) { 224 resize(); 225 } else { 226 break; 227 } 228 } 229 if (threadCount < lastThread) { 230 // avoid retaining pointers to threads that have ended 231 Arrays.fill(threads, threadCount, lastThread, null); 232 } 233 lastThread = threadCount; 234 return threads; 235 } 236 } 237 238 /** 239 * Starts profiler sampling at the specified rate. 240 * 241 * @param samplesPerSecond The number of samples to take a second 242 */ 243 public void start(int samplesPerSecond) { 244 if (samplesPerSecond < 1) { 245 throw new IllegalArgumentException("samplesPerSecond < 1"); 246 } 247 if (sampler != null) { 248 throw new IllegalStateException("profiling already started"); 249 } 250 sampler = new Sampler(); 251 timer.scheduleAtFixedRate(sampler, 0, 1000/samplesPerSecond); 252 } 253 254 /** 255 * Stops profiler sampling. It can be restarted with {@link 256 * #start(int)} to continue sampling. 257 */ 258 public void stop() { 259 if (sampler == null) { 260 return; 261 } 262 sampler.cancel(); 263 sampler = null; 264 } 265 266 /** 267 * Shuts down profiling after which it can not be restarted. It is 268 * important to shut down profiling when done to free resources 269 * used by the profiler. Shutting down the profiler also stops the 270 * profiling if that has not already been done. 271 */ 272 public void shutdown() { 273 stop(); 274 timer.cancel(); 275 } 276 277 /** 278 * The Sampler does the real work of the profiler. 279 * 280 * At every sample time, it asks the thread set for the set 281 * of threads to sample. It maintains a history of thread creation 282 * and death events based on changes observed to the threads 283 * returned by the {@code ThreadSet}. 284 * 285 * For each thread to be sampled, a stack is collected and used to 286 * update the set of collected samples. Stacks are truncated to a 287 * maximum depth. There is no way to tell if a stack has been truncated. 288 */ 289 private class Sampler extends TimerTask { 290 291 private Thread timerThread; 292 private Thread[] currentThreads = new Thread[0]; 293 private final Trace mutableTrace = new Trace(); 294 295 public void run() { 296 if (timerThread == null) { 297 timerThread = Thread.currentThread(); 298 } 299 300 // process thread creation and death first so that we 301 // assign thread ids to any new threads before allocating 302 // new stacks for them 303 Thread[] newThreads = threadSet.threads(); 304 if (!Arrays.equals(currentThreads, newThreads)) { 305 updateThreadHistory(currentThreads, newThreads); 306 currentThreads = newThreads.clone(); 307 } 308 309 for (Thread thread : currentThreads) { 310 if (thread == null) { 311 break; 312 } 313 if (thread == timerThread) { 314 continue; 315 } 316 317 // TODO replace with a VMStack.getThreadStackTrace 318 // variant to avoid allocating unneeded elements 319 StackTraceElement[] stack = thread.getStackTrace(); 320 if (stack.length > depth) { 321 stack = Arrays.copyOfRange(stack, 0, depth); 322 } 323 324 mutableTrace.threadId = threadIds.get(thread); 325 mutableTrace.stack = stack; 326 327 int[] count = traces.get(mutableTrace); 328 if (count == null) { 329 Trace trace = new Trace(nextTraceId++, mutableTrace); 330 count = new int[1]; 331 traces.put(trace, count); 332 } 333 count[0]++; 334 } 335 } 336 337 private void updateThreadHistory(Thread[] oldThreads, Thread[] newThreads) { 338 // thread start/stop shouldn't happen too often and 339 // these aren't too big, so hopefully this approach 340 // won't be too slow... 341 Set<Thread> n = new HashSet<Thread>(Arrays.asList(newThreads)); 342 Set<Thread> o = new HashSet<Thread>(Arrays.asList(oldThreads)); 343 344 // added = new-old 345 Set<Thread> added = new HashSet<Thread>(n); 346 added.removeAll(o); 347 348 // removed = old-new 349 Set<Thread> removed = new HashSet<Thread>(o); 350 removed.removeAll(n); 351 352 for (Thread thread : added) { 353 if (thread == null) { 354 continue; 355 } 356 if (thread == timerThread) { 357 continue; 358 } 359 int threadId = nextThreadId++; 360 threadIds.put(thread, threadId); 361 ThreadEvent event = ThreadEvent.start(nextObjectId++,threadId, thread); 362 threadHistory.add(event); 363 } 364 for (Thread thread : removed) { 365 if (thread == null) { 366 continue; 367 } 368 if (thread == timerThread) { 369 continue; 370 } 371 int threadId = threadIds.remove(thread); 372 ThreadEvent event = ThreadEvent.stop(threadId); 373 threadHistory.add(event); 374 } 375 } 376 } 377 378 private enum ThreadEventType { START, STOP }; 379 380 /** 381 * ThreadEvent represents thread creation and death events for 382 * reporting. It provides a record of the thread and thread group 383 * names for tying samples back to their source thread. 384 */ 385 private static class ThreadEvent { 386 387 private final ThreadEventType type; 388 private final int objectId; 389 private final int threadId; 390 private final String threadName; 391 private final String groupName; 392 393 private static ThreadEvent start(int objectId, int threadId, Thread thread) { 394 return new ThreadEvent(ThreadEventType.START, objectId, threadId, thread); 395 } 396 397 private static ThreadEvent stop(int threadId) { 398 return new ThreadEvent(ThreadEventType.STOP, threadId); 399 } 400 401 private ThreadEvent(ThreadEventType type, int objectId, int threadId, Thread thread) { 402 this.type = ThreadEventType.START; 403 this.objectId = objectId; 404 this.threadId = threadId; 405 this.threadName = thread.getName(); 406 this.groupName = thread.getThreadGroup().getName(); 407 } 408 409 private ThreadEvent(ThreadEventType type, int threadId) { 410 this.type = ThreadEventType.STOP; 411 this.objectId = -1; 412 this.threadId = threadId; 413 this.threadName = null; 414 this.groupName = null; 415 } 416 417 @Override 418 public String toString() { 419 switch (type) { 420 case START: 421 return String.format( 422 "THREAD START (obj=%d, id = %d, name=\"%s\", group=\"%s\")", 423 objectId, threadId, threadName, groupName); 424 case STOP: 425 return String.format("THREAD END (id = %d)", threadId); 426 } 427 throw new IllegalStateException(type.toString()); 428 } 429 } 430 431 /** 432 * A Trace represents a unique stack trace for a specific thread. 433 */ 434 private static class Trace { 435 436 private final int traceId; 437 private int threadId; 438 private StackTraceElement[] stack; 439 440 private Trace() { 441 this.traceId = -1; 442 } 443 444 private Trace(int traceId, Trace mutableTrace) { 445 this.traceId = traceId; 446 this.threadId = mutableTrace.threadId; 447 this.stack = mutableTrace.stack; 448 } 449 450 protected int getThreadId() { 451 return threadId; 452 } 453 454 protected StackTraceElement[] getStack() { 455 return stack; 456 } 457 458 @Override 459 public final int hashCode() { 460 int result = 17; 461 result = 31 * result + getThreadId(); 462 result = 31 * result + Arrays.hashCode(getStack()); 463 return result; 464 } 465 466 @Override 467 public final boolean equals(Object o) { 468 Trace s = (Trace) o; 469 return getThreadId() == s.getThreadId() && Arrays.equals(getStack(), s.getStack()); 470 } 471 } 472 473 /** 474 * Prints the profiler's collected data in hprof format to the 475 * specified {@code File}. See the {@link #writeHprofData(PrintStream) 476 * PrintStream} variant for more information. 477 */ 478 public void writeHprofData(File file) throws IOException { 479 PrintStream out = null; 480 try { 481 out = new PrintStream(new BufferedOutputStream(new FileOutputStream(file))); 482 writeHprofData(out); 483 } finally { 484 if (out != null) { 485 out.close(); 486 } 487 } 488 } 489 490 private static final class SampleComparator implements Comparator<Entry<Trace, int[]>> { 491 private static final SampleComparator INSTANCE = new SampleComparator(); 492 public int compare(Entry<Trace, int[]> e1, Entry<Trace, int[]> e2) { 493 return e2.getValue()[0] - e1.getValue()[0]; 494 } 495 } 496 497 /** 498 * Prints the profiler's collected data in hprof format to the 499 * specified {@code PrintStream}. The profiler needs to be 500 * stopped, but not necessarily shut down, in order to produce a 501 * report. 502 */ 503 public void writeHprofData(PrintStream out) { 504 if (sampler != null) { 505 throw new IllegalStateException("cannot print hprof data while sampling"); 506 } 507 508 for (ThreadEvent e : threadHistory) { 509 out.println(e); 510 } 511 512 List<Entry<Trace, int[]>> samples = new ArrayList<Entry<Trace, int[]>>(traces.entrySet()); 513 Collections.sort(samples, SampleComparator.INSTANCE); 514 int total = 0; 515 for (Entry<Trace, int[]> sample : samples) { 516 Trace trace = sample.getKey(); 517 int count = sample.getValue()[0]; 518 total += count; 519 out.printf("TRACE %d: (thread=%d)\n", trace.traceId, trace.threadId); 520 for (StackTraceElement e : trace.stack) { 521 out.printf("\t%s\n", e); 522 } 523 } 524 Date now = new Date(); 525 // "CPU SAMPLES BEGIN (total = 826) Wed Jul 21 12:03:46 2010" 526 out.printf("CPU SAMPLES BEGIN (total = %d) %ta %tb %td %tT %tY\n", 527 total, now, now, now, now, now); 528 out.printf("rank self accum count trace method\n"); 529 int rank = 0; 530 double accum = 0; 531 for (Entry<Trace, int[]> sample : samples) { 532 rank++; 533 Trace trace = sample.getKey(); 534 int count = sample.getValue()[0]; 535 double self = (double)count/(double)total; 536 accum += self; 537 538 // " 1 65.62% 65.62% 542 300302 java.lang.Long.parseLong" 539 out.printf("% 4d% 6.2f%%% 6.2f%% % 7d % 5d %s.%s\n", 540 rank, self*100, accum*100, count, trace.traceId, 541 trace.stack[0].getClassName(), 542 trace.stack[0].getMethodName()); 543 } 544 out.printf("CPU SAMPLES END\n"); 545 } 546 } 547