blob: cde4177d6d837f56a9bab34645e01762621200d0 [file] [log] [blame]
Dave Allison0aded082013-11-07 13:15:11 -08001/*
2 * Copyright (C) 2011 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#include "profiler.h"
18
Calin Juravle9dae5b42014-04-07 16:36:21 +030019#include <fstream>
Dave Allison0aded082013-11-07 13:15:11 -080020#include <sys/uio.h>
Dave Allison39c3bfb2014-01-28 18:33:52 -080021#include <sys/file.h>
Dave Allison0aded082013-11-07 13:15:11 -080022
23#include "base/stl_util.h"
24#include "base/unix_file/fd_file.h"
25#include "class_linker.h"
26#include "common_throws.h"
27#include "debugger.h"
28#include "dex_file-inl.h"
29#include "instrumentation.h"
30#include "mirror/art_method-inl.h"
31#include "mirror/class-inl.h"
32#include "mirror/dex_cache.h"
33#include "mirror/object_array-inl.h"
34#include "mirror/object-inl.h"
Dave Allison0aded082013-11-07 13:15:11 -080035#include "os.h"
36#include "scoped_thread_state_change.h"
37#include "ScopedLocalRef.h"
38#include "thread.h"
39#include "thread_list.h"
Dave Allison4a7867b2014-01-30 17:44:12 -080040
41#ifdef HAVE_ANDROID_OS
42#include "cutils/properties.h"
43#endif
44
Dave Allison0aded082013-11-07 13:15:11 -080045#if !defined(ART_USE_PORTABLE_COMPILER)
46#include "entrypoints/quick/quick_entrypoints.h"
47#endif
48
49namespace art {
50
51BackgroundMethodSamplingProfiler* BackgroundMethodSamplingProfiler::profiler_ = nullptr;
52pthread_t BackgroundMethodSamplingProfiler::profiler_pthread_ = 0U;
53volatile bool BackgroundMethodSamplingProfiler::shutting_down_ = false;
54
Dave Allison0aded082013-11-07 13:15:11 -080055// TODO: this profiler runs regardless of the state of the machine. Maybe we should use the
56// wakelock or something to modify the run characteristics. This can be done when we
57// have some performance data after it's been used for a while.
58
Wei Jin445220d2014-06-20 15:56:53 -070059// Walk through the method within depth of max_depth_ on the Java stack
60class BoundedStackVisitor : public StackVisitor {
61 public:
62 BoundedStackVisitor(std::vector<std::pair<mirror::ArtMethod*, uint32_t>>* stack,
63 Thread* thread, uint32_t max_depth)
64 SHARED_LOCKS_REQUIRED(Locks::mutator_lock_)
65 : StackVisitor(thread, NULL), stack_(stack), max_depth_(max_depth), depth_(0) {
66 }
67
68 bool VisitFrame() SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) {
69 mirror::ArtMethod* m = GetMethod();
70 if (m->IsRuntimeMethod()) {
71 return true;
72 }
73 uint32_t dex_pc_ = GetDexPc();
74 stack_->push_back(std::make_pair(m, dex_pc_));
75 ++depth_;
76 if (depth_ < max_depth_) {
77 return true;
78 } else {
79 return false;
80 }
81 }
82
83 private:
84 std::vector<std::pair<mirror::ArtMethod*, uint32_t>>* stack_;
85 const uint32_t max_depth_;
86 uint32_t depth_;
87};
Dave Allison0aded082013-11-07 13:15:11 -080088
89// This is called from either a thread list traversal or from a checkpoint. Regardless
90// of which caller, the mutator lock must be held.
91static void GetSample(Thread* thread, void* arg) SHARED_LOCKS_REQUIRED(Locks::mutator_lock_) {
92 BackgroundMethodSamplingProfiler* profiler =
93 reinterpret_cast<BackgroundMethodSamplingProfiler*>(arg);
Wei Jin445220d2014-06-20 15:56:53 -070094 const ProfilerOptions profile_options = profiler->GetProfilerOptions();
95 switch (profile_options.GetProfileType()) {
96 case kProfilerMethod: {
97 mirror::ArtMethod* method = thread->GetCurrentMethod(nullptr);
98 if (false && method == nullptr) {
99 LOG(INFO) << "No current method available";
100 std::ostringstream os;
101 thread->Dump(os);
102 std::string data(os.str());
103 LOG(INFO) << data;
104 }
105 profiler->RecordMethod(method);
106 break;
107 }
108 case kProfilerBoundedStack: {
109 std::vector<InstructionLocation> stack;
110 uint32_t max_depth = profile_options.GetMaxStackDepth();
111 BoundedStackVisitor bounded_stack_visitor(&stack, thread, max_depth);
112 bounded_stack_visitor.WalkStack();
113 profiler->RecordStack(stack);
114 break;
115 }
116 default:
117 LOG(INFO) << "This profile type is not implemented.";
Dave Allison0aded082013-11-07 13:15:11 -0800118 }
Dave Allison0aded082013-11-07 13:15:11 -0800119}
120
Dave Allison0aded082013-11-07 13:15:11 -0800121// A closure that is called by the thread checkpoint code.
Ian Rogers7b078e82014-09-10 14:44:24 -0700122class SampleCheckpoint FINAL : public Closure {
Dave Allison0aded082013-11-07 13:15:11 -0800123 public:
124 explicit SampleCheckpoint(BackgroundMethodSamplingProfiler* const profiler) :
125 profiler_(profiler) {}
126
Ian Rogers7b078e82014-09-10 14:44:24 -0700127 void Run(Thread* thread) OVERRIDE {
Dave Allison0aded082013-11-07 13:15:11 -0800128 Thread* self = Thread::Current();
129 if (thread == nullptr) {
130 LOG(ERROR) << "Checkpoint with nullptr thread";
131 return;
132 }
133
134 // Grab the mutator lock (shared access).
135 ScopedObjectAccess soa(self);
136
137 // Grab a sample.
138 GetSample(thread, this->profiler_);
139
140 // And finally tell the barrier that we're done.
141 this->profiler_->GetBarrier().Pass(self);
142 }
143
144 private:
145 BackgroundMethodSamplingProfiler* const profiler_;
146};
147
148bool BackgroundMethodSamplingProfiler::ShuttingDown(Thread* self) {
149 MutexLock mu(self, *Locks::profiler_lock_);
150 return shutting_down_;
151}
152
153void* BackgroundMethodSamplingProfiler::RunProfilerThread(void* arg) {
154 Runtime* runtime = Runtime::Current();
155 BackgroundMethodSamplingProfiler* profiler =
156 reinterpret_cast<BackgroundMethodSamplingProfiler*>(arg);
157
158 // Add a random delay for the first time run so that we don't hammer the CPU
159 // with all profiles running at the same time.
160 const int kRandomDelayMaxSecs = 30;
161 const double kMaxBackoffSecs = 24*60*60; // Max backoff time.
162
163 srand(MicroTime() * getpid());
164 int startup_delay = rand() % kRandomDelayMaxSecs; // random delay for startup.
165
166
167 CHECK(runtime->AttachCurrentThread("Profiler", true, runtime->GetSystemThreadGroup(),
168 !runtime->IsCompiler()));
169
170 Thread* self = Thread::Current();
171
Calin Juravlec1b643c2014-05-30 23:44:11 +0100172 double backoff = 1.0;
Dave Allison0aded082013-11-07 13:15:11 -0800173 while (true) {
174 if (ShuttingDown(self)) {
175 break;
176 }
177
178 {
179 // wait until we need to run another profile
Calin Juravlec1b643c2014-05-30 23:44:11 +0100180 uint64_t delay_secs = profiler->options_.GetPeriodS() * backoff;
Dave Allison0aded082013-11-07 13:15:11 -0800181
182 // Add a startup delay to prevent all the profiles running at once.
183 delay_secs += startup_delay;
184
185 // Immediate startup for benchmarking?
Calin Juravlec1b643c2014-05-30 23:44:11 +0100186 if (profiler->options_.GetStartImmediately() && startup_delay > 0) {
Dave Allison0aded082013-11-07 13:15:11 -0800187 delay_secs = 0;
188 }
189
190 startup_delay = 0;
191
Brian Carlstrom4d466a82014-05-08 19:05:29 -0700192 VLOG(profiler) << "Delaying profile start for " << delay_secs << " secs";
Dave Allison0aded082013-11-07 13:15:11 -0800193 MutexLock mu(self, profiler->wait_lock_);
194 profiler->period_condition_.TimedWait(self, delay_secs * 1000, 0);
Ian Rogers7b078e82014-09-10 14:44:24 -0700195 // We were either signaled by Stop or timedout, in either case ignore the timed out result.
Dave Allison0aded082013-11-07 13:15:11 -0800196
197 // Expand the backoff by its coefficient, but don't go beyond the max.
Calin Juravlec1b643c2014-05-30 23:44:11 +0100198 backoff = std::min(backoff * profiler->options_.GetBackoffCoefficient(), kMaxBackoffSecs);
Dave Allison0aded082013-11-07 13:15:11 -0800199 }
200
201 if (ShuttingDown(self)) {
202 break;
203 }
204
205
206 uint64_t start_us = MicroTime();
Calin Juravlec1b643c2014-05-30 23:44:11 +0100207 uint64_t end_us = start_us + profiler->options_.GetDurationS() * UINT64_C(1000000);
Dave Allison0aded082013-11-07 13:15:11 -0800208 uint64_t now_us = start_us;
209
Calin Juravlec1b643c2014-05-30 23:44:11 +0100210 VLOG(profiler) << "Starting profiling run now for "
211 << PrettyDuration((end_us - start_us) * 1000);
Dave Allison0aded082013-11-07 13:15:11 -0800212
213 SampleCheckpoint check_point(profiler);
214
Dave Allison39c3bfb2014-01-28 18:33:52 -0800215 size_t valid_samples = 0;
Dave Allison0aded082013-11-07 13:15:11 -0800216 while (now_us < end_us) {
217 if (ShuttingDown(self)) {
218 break;
219 }
220
Calin Juravlec1b643c2014-05-30 23:44:11 +0100221 usleep(profiler->options_.GetIntervalUs()); // Non-interruptible sleep.
Dave Allison0aded082013-11-07 13:15:11 -0800222
223 ThreadList* thread_list = runtime->GetThreadList();
224
225 profiler->profiler_barrier_->Init(self, 0);
Dave Allison39c3bfb2014-01-28 18:33:52 -0800226 size_t barrier_count = thread_list->RunCheckpointOnRunnableThreads(&check_point);
227
228 // All threads are suspended, nothing to do.
229 if (barrier_count == 0) {
230 now_us = MicroTime();
231 continue;
232 }
233
234 valid_samples += barrier_count;
Dave Allison0aded082013-11-07 13:15:11 -0800235
Wei Jin6a586912014-05-21 16:07:40 -0700236 ScopedThreadStateChange tsc(self, kWaitingForCheckPointsToRun);
Dave Allison0aded082013-11-07 13:15:11 -0800237
238 // Wait for the barrier to be crossed by all runnable threads. This wait
239 // is done with a timeout so that we can detect problems with the checkpoint
240 // running code. We should never see this.
241 const uint32_t kWaitTimeoutMs = 10000;
Dave Allison0aded082013-11-07 13:15:11 -0800242
Dave Allison0aded082013-11-07 13:15:11 -0800243 // Wait for all threads to pass the barrier.
Ian Rogers7b078e82014-09-10 14:44:24 -0700244 bool timed_out = profiler->profiler_barrier_->Increment(self, barrier_count, kWaitTimeoutMs);
Dave Allison0aded082013-11-07 13:15:11 -0800245
246 // We should never get a timeout. If we do, it suggests a problem with the checkpoint
247 // code. Crash the process in this case.
Ian Rogers7b078e82014-09-10 14:44:24 -0700248 CHECK(!timed_out);
Dave Allison0aded082013-11-07 13:15:11 -0800249
Dave Allison0aded082013-11-07 13:15:11 -0800250 // Update the current time.
251 now_us = MicroTime();
252 }
253
Wei Jin6a586912014-05-21 16:07:40 -0700254 if (valid_samples > 0) {
Dave Allison0aded082013-11-07 13:15:11 -0800255 // After the profile has been taken, write it out.
256 ScopedObjectAccess soa(self); // Acquire the mutator lock.
257 uint32_t size = profiler->WriteProfile();
Brian Carlstrom4d466a82014-05-08 19:05:29 -0700258 VLOG(profiler) << "Profile size: " << size;
Dave Allison0aded082013-11-07 13:15:11 -0800259 }
260 }
261
262 LOG(INFO) << "Profiler shutdown";
263 runtime->DetachCurrentThread();
264 return nullptr;
265}
266
267// Write out the profile file if we are generating a profile.
268uint32_t BackgroundMethodSamplingProfiler::WriteProfile() {
Calin Juravlec1b643c2014-05-30 23:44:11 +0100269 std::string full_name = output_filename_;
Brian Carlstrom4d466a82014-05-08 19:05:29 -0700270 VLOG(profiler) << "Saving profile to " << full_name;
Dave Allison0aded082013-11-07 13:15:11 -0800271
Dave Allison39c3bfb2014-01-28 18:33:52 -0800272 int fd = open(full_name.c_str(), O_RDWR);
273 if (fd < 0) {
274 // Open failed.
275 LOG(ERROR) << "Failed to open profile file " << full_name;
Dave Allison0aded082013-11-07 13:15:11 -0800276 return 0;
277 }
Dave Allison39c3bfb2014-01-28 18:33:52 -0800278
279 // Lock the file for exclusive access. This will block if another process is using
280 // the file.
281 int err = flock(fd, LOCK_EX);
282 if (err < 0) {
283 LOG(ERROR) << "Failed to lock profile file " << full_name;
284 return 0;
285 }
286
287 // Read the previous profile.
Wei Jina93b0bb2014-06-09 16:19:15 -0700288 profile_table_.ReadPrevious(fd, options_.GetProfileType());
Dave Allison39c3bfb2014-01-28 18:33:52 -0800289
290 // Move back to the start of the file.
291 lseek(fd, 0, SEEK_SET);
292
293 // Format the profile output and write to the file.
Dave Allison0aded082013-11-07 13:15:11 -0800294 std::ostringstream os;
295 uint32_t num_methods = DumpProfile(os);
296 std::string data(os.str());
Dave Allison39c3bfb2014-01-28 18:33:52 -0800297 const char *p = data.c_str();
298 size_t length = data.length();
299 size_t full_length = length;
300 do {
301 int n = ::write(fd, p, length);
302 p += n;
303 length -= n;
304 } while (length > 0);
305
306 // Truncate the file to the new length.
307 ftruncate(fd, full_length);
308
309 // Now unlock the file, allowing another process in.
310 err = flock(fd, LOCK_UN);
311 if (err < 0) {
312 LOG(ERROR) << "Failed to unlock profile file " << full_name;
313 }
314
315 // Done, close the file.
316 ::close(fd);
317
318 // Clean the profile for the next time.
319 CleanProfile();
320
Dave Allison0aded082013-11-07 13:15:11 -0800321 return num_methods;
322}
323
Calin Juravlec1b643c2014-05-30 23:44:11 +0100324bool BackgroundMethodSamplingProfiler::Start(
325 const std::string& output_filename, const ProfilerOptions& options) {
326 if (!options.IsEnabled()) {
Calin Juravlec1b643c2014-05-30 23:44:11 +0100327 return false;
328 }
329
330 CHECK(!output_filename.empty());
331
Dave Allison0aded082013-11-07 13:15:11 -0800332 Thread* self = Thread::Current();
333 {
334 MutexLock mu(self, *Locks::profiler_lock_);
335 // Don't start two profiler threads.
336 if (profiler_ != nullptr) {
Calin Juravlec1b643c2014-05-30 23:44:11 +0100337 return true;
Dave Allison0aded082013-11-07 13:15:11 -0800338 }
339 }
340
Calin Juravlec1b643c2014-05-30 23:44:11 +0100341 LOG(INFO) << "Starting profiler using output file: " << output_filename
342 << " and options: " << options;
Dave Allison0aded082013-11-07 13:15:11 -0800343 {
344 MutexLock mu(self, *Locks::profiler_lock_);
Calin Juravlec1b643c2014-05-30 23:44:11 +0100345 profiler_ = new BackgroundMethodSamplingProfiler(output_filename, options);
Dave Allison0aded082013-11-07 13:15:11 -0800346
347 CHECK_PTHREAD_CALL(pthread_create, (&profiler_pthread_, nullptr, &RunProfilerThread,
348 reinterpret_cast<void*>(profiler_)),
349 "Profiler thread");
350 }
Calin Juravlec1b643c2014-05-30 23:44:11 +0100351 return true;
Dave Allison0aded082013-11-07 13:15:11 -0800352}
353
354
355
356void BackgroundMethodSamplingProfiler::Stop() {
357 BackgroundMethodSamplingProfiler* profiler = nullptr;
358 pthread_t profiler_pthread = 0U;
359 {
360 MutexLock trace_mu(Thread::Current(), *Locks::profiler_lock_);
Wei Jin6a586912014-05-21 16:07:40 -0700361 CHECK(!shutting_down_);
Dave Allison0aded082013-11-07 13:15:11 -0800362 profiler = profiler_;
363 shutting_down_ = true;
364 profiler_pthread = profiler_pthread_;
365 }
366
367 // Now wake up the sampler thread if it sleeping.
368 {
369 MutexLock profile_mu(Thread::Current(), profiler->wait_lock_);
370 profiler->period_condition_.Signal(Thread::Current());
371 }
372 // Wait for the sample thread to stop.
373 CHECK_PTHREAD_CALL(pthread_join, (profiler_pthread, nullptr), "profiler thread shutdown");
374
375 {
376 MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
377 profiler_ = nullptr;
378 }
379 delete profiler;
380}
381
382
383void BackgroundMethodSamplingProfiler::Shutdown() {
384 Stop();
385}
386
Calin Juravlec1b643c2014-05-30 23:44:11 +0100387BackgroundMethodSamplingProfiler::BackgroundMethodSamplingProfiler(
388 const std::string& output_filename, const ProfilerOptions& options)
389 : output_filename_(output_filename),
390 options_(options),
Dave Allison0aded082013-11-07 13:15:11 -0800391 wait_lock_("Profile wait lock"),
392 period_condition_("Profile condition", wait_lock_),
393 profile_table_(wait_lock_),
394 profiler_barrier_(new Barrier(0)) {
395 // Populate the filtered_methods set.
396 // This is empty right now, but to add a method, do this:
397 //
398 // filtered_methods_.insert("void java.lang.Object.wait(long, int)");
399}
400
Wei Jin445220d2014-06-20 15:56:53 -0700401// Filter out methods the profiler doesn't want to record.
402// We require mutator lock since some statistics will be updated here.
403bool BackgroundMethodSamplingProfiler::ProcessMethod(mirror::ArtMethod* method) {
Dave Allison0aded082013-11-07 13:15:11 -0800404 if (method == nullptr) {
405 profile_table_.NullMethod();
406 // Don't record a nullptr method.
Wei Jin445220d2014-06-20 15:56:53 -0700407 return false;
Dave Allison0aded082013-11-07 13:15:11 -0800408 }
409
410 mirror::Class* cls = method->GetDeclaringClass();
411 if (cls != nullptr) {
412 if (cls->GetClassLoader() == nullptr) {
413 // Don't include things in the boot
414 profile_table_.BootMethod();
Wei Jin445220d2014-06-20 15:56:53 -0700415 return false;
Dave Allison0aded082013-11-07 13:15:11 -0800416 }
417 }
418
419 bool is_filtered = false;
420
Mathieu Chartierbfd9a432014-05-21 17:43:44 -0700421 if (strcmp(method->GetName(), "<clinit>") == 0) {
Dave Allison0aded082013-11-07 13:15:11 -0800422 // always filter out class init
423 is_filtered = true;
424 }
425
426 // Filter out methods by name if there are any.
427 if (!is_filtered && filtered_methods_.size() > 0) {
428 std::string method_full_name = PrettyMethod(method);
429
430 // Don't include specific filtered methods.
431 is_filtered = filtered_methods_.count(method_full_name) != 0;
432 }
Wei Jin445220d2014-06-20 15:56:53 -0700433 return !is_filtered;
434}
Dave Allison0aded082013-11-07 13:15:11 -0800435
Wei Jin445220d2014-06-20 15:56:53 -0700436// A method has been hit, record its invocation in the method map.
437// The mutator_lock must be held (shared) when this is called.
438void BackgroundMethodSamplingProfiler::RecordMethod(mirror::ArtMethod* method) {
Dave Allison0aded082013-11-07 13:15:11 -0800439 // Add to the profile table unless it is filtered out.
Wei Jin445220d2014-06-20 15:56:53 -0700440 if (ProcessMethod(method)) {
441 profile_table_.Put(method);
442 }
443}
444
445// Record the current bounded stack into sampling results.
446void BackgroundMethodSamplingProfiler::RecordStack(const std::vector<InstructionLocation>& stack) {
447 if (stack.size() == 0) {
448 return;
449 }
450 // Get the method on top of the stack. We use this method to perform filtering.
451 mirror::ArtMethod* method = stack.front().first;
452 if (ProcessMethod(method)) {
453 profile_table_.PutStack(stack);
Dave Allison0aded082013-11-07 13:15:11 -0800454 }
455}
456
457// Clean out any recordings for the method traces.
458void BackgroundMethodSamplingProfiler::CleanProfile() {
459 profile_table_.Clear();
460}
461
462uint32_t BackgroundMethodSamplingProfiler::DumpProfile(std::ostream& os) {
Wei Jina93b0bb2014-06-09 16:19:15 -0700463 return profile_table_.Write(os, options_.GetProfileType());
Dave Allison0aded082013-11-07 13:15:11 -0800464}
465
466// Profile Table.
467// This holds a mapping of mirror::ArtMethod* to a count of how many times a sample
468// hit it at the top of the stack.
469ProfileSampleResults::ProfileSampleResults(Mutex& lock) : lock_(lock), num_samples_(0),
470 num_null_methods_(0),
471 num_boot_methods_(0) {
472 for (int i = 0; i < kHashSize; i++) {
473 table[i] = nullptr;
474 }
Wei Jin445220d2014-06-20 15:56:53 -0700475 method_context_table = nullptr;
476 stack_trie_root_ = nullptr;
Dave Allison0aded082013-11-07 13:15:11 -0800477}
478
479ProfileSampleResults::~ProfileSampleResults() {
Wei Jina93b0bb2014-06-09 16:19:15 -0700480 Clear();
Dave Allison0aded082013-11-07 13:15:11 -0800481}
482
Calin Juravlebb0b53f2014-05-23 17:33:29 +0100483// Add a method to the profile table. If it's the first time the method
Dave Allison0aded082013-11-07 13:15:11 -0800484// has been seen, add it with count=1, otherwise increment the count.
485void ProfileSampleResults::Put(mirror::ArtMethod* method) {
Wei Jina93b0bb2014-06-09 16:19:15 -0700486 MutexLock mu(Thread::Current(), lock_);
Dave Allison0aded082013-11-07 13:15:11 -0800487 uint32_t index = Hash(method);
488 if (table[index] == nullptr) {
489 table[index] = new Map();
490 }
491 Map::iterator i = table[index]->find(method);
492 if (i == table[index]->end()) {
493 (*table[index])[method] = 1;
494 } else {
495 i->second++;
496 }
497 num_samples_++;
Wei Jina93b0bb2014-06-09 16:19:15 -0700498}
499
Wei Jin445220d2014-06-20 15:56:53 -0700500// Add a bounded stack to the profile table. Only the count of the method on
501// top of the frame will be increased.
502void ProfileSampleResults::PutStack(const std::vector<InstructionLocation>& stack) {
Wei Jina93b0bb2014-06-09 16:19:15 -0700503 MutexLock mu(Thread::Current(), lock_);
Wei Jin445220d2014-06-20 15:56:53 -0700504 ScopedObjectAccess soa(Thread::Current());
505 if (stack_trie_root_ == nullptr) {
506 // The root of the stack trie is a dummy node so that we don't have to maintain
507 // a collection of tries.
508 stack_trie_root_ = new StackTrieNode();
Wei Jina93b0bb2014-06-09 16:19:15 -0700509 }
Wei Jin445220d2014-06-20 15:56:53 -0700510
511 StackTrieNode* current = stack_trie_root_;
512 if (stack.size() == 0) {
513 current->IncreaseCount();
514 return;
515 }
516
517 for (std::vector<InstructionLocation>::const_reverse_iterator iter = stack.rbegin();
518 iter != stack.rend(); ++iter) {
519 InstructionLocation inst_loc = *iter;
520 mirror::ArtMethod* method = inst_loc.first;
521 if (method == nullptr) {
522 // skip null method
523 continue;
524 }
525 uint32_t dex_pc = inst_loc.second;
526 uint32_t method_idx = method->GetDexMethodIndex();
527 const DexFile* dex_file = method->GetDeclaringClass()->GetDexCache()->GetDexFile();
528 MethodReference method_ref(dex_file, method_idx);
529 StackTrieNode* child = current->FindChild(method_ref, dex_pc);
530 if (child != nullptr) {
531 current = child;
Wei Jina93b0bb2014-06-09 16:19:15 -0700532 } else {
Wei Jin445220d2014-06-20 15:56:53 -0700533 uint32_t method_size = 0;
534 const DexFile::CodeItem* codeitem = method->GetCodeItem();
535 if (codeitem != nullptr) {
536 method_size = codeitem->insns_size_in_code_units_;
537 }
538 StackTrieNode* new_node = new StackTrieNode(method_ref, dex_pc, method_size, current);
539 current->AppendChild(new_node);
540 current = new_node;
Wei Jina93b0bb2014-06-09 16:19:15 -0700541 }
542 }
Wei Jin445220d2014-06-20 15:56:53 -0700543
544 if (current != stack_trie_root_ && current->GetCount() == 0) {
545 // Insert into method_context table;
546 if (method_context_table == nullptr) {
547 method_context_table = new MethodContextMap();
548 }
549 MethodReference method = current->GetMethod();
550 MethodContextMap::iterator i = method_context_table->find(method);
551 if (i == method_context_table->end()) {
552 TrieNodeSet* node_set = new TrieNodeSet();
553 node_set->insert(current);
554 (*method_context_table)[method] = node_set;
555 } else {
556 TrieNodeSet* node_set = i->second;
557 node_set->insert(current);
558 }
559 }
560 current->IncreaseCount();
Wei Jina93b0bb2014-06-09 16:19:15 -0700561 num_samples_++;
Dave Allison0aded082013-11-07 13:15:11 -0800562}
563
Dave Allison39c3bfb2014-01-28 18:33:52 -0800564// Write the profile table to the output stream. Also merge with the previous profile.
Wei Jina93b0bb2014-06-09 16:19:15 -0700565uint32_t ProfileSampleResults::Write(std::ostream& os, ProfileDataType type) {
Dave Allison0aded082013-11-07 13:15:11 -0800566 ScopedObjectAccess soa(Thread::Current());
Dave Allison39c3bfb2014-01-28 18:33:52 -0800567 num_samples_ += previous_num_samples_;
568 num_null_methods_ += previous_num_null_methods_;
569 num_boot_methods_ += previous_num_boot_methods_;
570
Calin Juravlec1b643c2014-05-30 23:44:11 +0100571 VLOG(profiler) << "Profile: "
572 << num_samples_ << "/" << num_null_methods_ << "/" << num_boot_methods_;
Dave Allison0aded082013-11-07 13:15:11 -0800573 os << num_samples_ << "/" << num_null_methods_ << "/" << num_boot_methods_ << "\n";
574 uint32_t num_methods = 0;
Wei Jina93b0bb2014-06-09 16:19:15 -0700575 if (type == kProfilerMethod) {
576 for (int i = 0 ; i < kHashSize; i++) {
577 Map *map = table[i];
578 if (map != nullptr) {
579 for (const auto &meth_iter : *map) {
580 mirror::ArtMethod *method = meth_iter.first;
581 std::string method_name = PrettyMethod(method);
Dave Allison39c3bfb2014-01-28 18:33:52 -0800582
Wei Jina93b0bb2014-06-09 16:19:15 -0700583 const DexFile::CodeItem* codeitem = method->GetCodeItem();
584 uint32_t method_size = 0;
585 if (codeitem != nullptr) {
586 method_size = codeitem->insns_size_in_code_units_;
587 }
588 uint32_t count = meth_iter.second;
Dave Allison39c3bfb2014-01-28 18:33:52 -0800589
Wei Jina93b0bb2014-06-09 16:19:15 -0700590 // Merge this profile entry with one from a previous run (if present). Also
591 // remove the previous entry.
592 PreviousProfile::iterator pi = previous_.find(method_name);
593 if (pi != previous_.end()) {
594 count += pi->second.count_;
595 previous_.erase(pi);
596 }
597 os << StringPrintf("%s/%u/%u\n", method_name.c_str(), count, method_size);
598 ++num_methods;
Dave Allison39c3bfb2014-01-28 18:33:52 -0800599 }
Wei Jina93b0bb2014-06-09 16:19:15 -0700600 }
601 }
Wei Jin445220d2014-06-20 15:56:53 -0700602 } else if (type == kProfilerBoundedStack) {
603 if (method_context_table != nullptr) {
604 for (const auto &method_iter : *method_context_table) {
605 MethodReference method = method_iter.first;
606 TrieNodeSet* node_set = method_iter.second;
607 std::string method_name = PrettyMethod(method.dex_method_index, *(method.dex_file));
608 uint32_t method_size = 0;
609 uint32_t total_count = 0;
610 PreviousContextMap new_context_map;
611 for (const auto &trie_node_i : *node_set) {
612 StackTrieNode* node = trie_node_i;
613 method_size = node->GetMethodSize();
614 uint32_t count = node->GetCount();
615 uint32_t dexpc = node->GetDexPC();
616 total_count += count;
Wei Jina93b0bb2014-06-09 16:19:15 -0700617
Wei Jin445220d2014-06-20 15:56:53 -0700618 StackTrieNode* current = node->GetParent();
619 // We go backward on the trie to retrieve context and dex_pc until the dummy root.
620 // The format of the context is "method_1@pc_1@method_2@pc_2@..."
621 std::vector<std::string> context_vector;
622 while (current != nullptr && current->GetParent() != nullptr) {
623 context_vector.push_back(StringPrintf("%s@%u",
624 PrettyMethod(current->GetMethod().dex_method_index, *(current->GetMethod().dex_file)).c_str(),
625 current->GetDexPC()));
626 current = current->GetParent();
Wei Jina93b0bb2014-06-09 16:19:15 -0700627 }
Wei Jin445220d2014-06-20 15:56:53 -0700628 std::string context_sig = Join(context_vector, '@');
629 new_context_map[std::make_pair(dexpc, context_sig)] = count;
630 }
Wei Jina93b0bb2014-06-09 16:19:15 -0700631
Wei Jin445220d2014-06-20 15:56:53 -0700632 PreviousProfile::iterator pi = previous_.find(method_name);
633 if (pi != previous_.end()) {
634 total_count += pi->second.count_;
635 PreviousContextMap* previous_context_map = pi->second.context_map_;
636 if (previous_context_map != nullptr) {
637 for (const auto &context_i : *previous_context_map) {
638 uint32_t count = context_i.second;
639 PreviousContextMap::iterator ci = new_context_map.find(context_i.first);
640 if (ci == new_context_map.end()) {
641 new_context_map[context_i.first] = count;
642 } else {
643 ci->second += count;
Wei Jina93b0bb2014-06-09 16:19:15 -0700644 }
645 }
Wei Jina93b0bb2014-06-09 16:19:15 -0700646 }
Wei Jin445220d2014-06-20 15:56:53 -0700647 delete previous_context_map;
648 previous_.erase(pi);
Wei Jina93b0bb2014-06-09 16:19:15 -0700649 }
Wei Jin445220d2014-06-20 15:56:53 -0700650 // We write out profile data with dex pc and context information in the following format:
651 // "method/total_count/size/[pc_1:count_1:context_1#pc_2:count_2:context_2#...]".
652 std::vector<std::string> context_count_vector;
653 for (const auto &context_i : new_context_map) {
654 context_count_vector.push_back(StringPrintf("%u:%u:%s", context_i.first.first,
655 context_i.second, context_i.first.second.c_str()));
656 }
657 os << StringPrintf("%s/%u/%u/[%s]\n", method_name.c_str(), total_count,
658 method_size, Join(context_count_vector, '#').c_str());
659 ++num_methods;
Dave Allison39c3bfb2014-01-28 18:33:52 -0800660 }
Dave Allison0aded082013-11-07 13:15:11 -0800661 }
662 }
Dave Allison39c3bfb2014-01-28 18:33:52 -0800663
664 // Now we write out the remaining previous methods.
Wei Jina93b0bb2014-06-09 16:19:15 -0700665 for (const auto &pi : previous_) {
666 if (type == kProfilerMethod) {
667 os << StringPrintf("%s/%u/%u\n", pi.first.c_str(), pi.second.count_, pi.second.method_size_);
Wei Jin445220d2014-06-20 15:56:53 -0700668 } else if (type == kProfilerBoundedStack) {
Wei Jina93b0bb2014-06-09 16:19:15 -0700669 os << StringPrintf("%s/%u/%u/[", pi.first.c_str(), pi.second.count_, pi.second.method_size_);
Wei Jin445220d2014-06-20 15:56:53 -0700670 PreviousContextMap* previous_context_map = pi.second.context_map_;
671 if (previous_context_map != nullptr) {
672 std::vector<std::string> context_count_vector;
673 for (const auto &context_i : *previous_context_map) {
674 context_count_vector.push_back(StringPrintf("%u:%u:%s", context_i.first.first,
675 context_i.second, context_i.first.second.c_str()));
Wei Jina93b0bb2014-06-09 16:19:15 -0700676 }
Wei Jin445220d2014-06-20 15:56:53 -0700677 os << Join(context_count_vector, '#');
Wei Jina93b0bb2014-06-09 16:19:15 -0700678 }
679 os << "]\n";
680 }
Dave Allison39c3bfb2014-01-28 18:33:52 -0800681 ++num_methods;
682 }
Dave Allison0aded082013-11-07 13:15:11 -0800683 return num_methods;
684}
685
686void ProfileSampleResults::Clear() {
687 num_samples_ = 0;
688 num_null_methods_ = 0;
689 num_boot_methods_ = 0;
690 for (int i = 0; i < kHashSize; i++) {
Wei Jina93b0bb2014-06-09 16:19:15 -0700691 delete table[i];
692 table[i] = nullptr;
Wei Jin445220d2014-06-20 15:56:53 -0700693 }
694 if (stack_trie_root_ != nullptr) {
695 stack_trie_root_->DeleteChildren();
696 delete stack_trie_root_;
697 stack_trie_root_ = nullptr;
698 if (method_context_table != nullptr) {
699 delete method_context_table;
700 method_context_table = nullptr;
Wei Jina93b0bb2014-06-09 16:19:15 -0700701 }
Wei Jina93b0bb2014-06-09 16:19:15 -0700702 }
703 for (auto &pi : previous_) {
Wei Jin445220d2014-06-20 15:56:53 -0700704 if (pi.second.context_map_ != nullptr) {
705 delete pi.second.context_map_;
706 pi.second.context_map_ = nullptr;
707 }
Dave Allison0aded082013-11-07 13:15:11 -0800708 }
Dave Allison39c3bfb2014-01-28 18:33:52 -0800709 previous_.clear();
Dave Allison0aded082013-11-07 13:15:11 -0800710}
711
712uint32_t ProfileSampleResults::Hash(mirror::ArtMethod* method) {
Ian Rogersef7d42f2014-01-06 12:55:46 -0800713 return (PointerToLowMemUInt32(method) >> 3) % kHashSize;
Dave Allison0aded082013-11-07 13:15:11 -0800714}
715
Dave Allison39c3bfb2014-01-28 18:33:52 -0800716// Read a single line into the given string. Returns true if everything OK, false
717// on EOF or error.
718static bool ReadProfileLine(int fd, std::string& line) {
719 char buf[4];
720 line.clear();
721 while (true) {
722 int n = read(fd, buf, 1); // TODO: could speed this up but is it worth it?
723 if (n != 1) {
724 return false;
725 }
726 if (buf[0] == '\n') {
727 break;
728 }
729 line += buf[0];
730 }
731 return true;
732}
733
Wei Jina93b0bb2014-06-09 16:19:15 -0700734void ProfileSampleResults::ReadPrevious(int fd, ProfileDataType type) {
Dave Allison39c3bfb2014-01-28 18:33:52 -0800735 // Reset counters.
736 previous_num_samples_ = previous_num_null_methods_ = previous_num_boot_methods_ = 0;
737
738 std::string line;
739
740 // The first line contains summary information.
741 if (!ReadProfileLine(fd, line)) {
742 return;
743 }
744 std::vector<std::string> summary_info;
745 Split(line, '/', summary_info);
746 if (summary_info.size() != 3) {
747 // Bad summary info. It should be count/nullcount/bootcount
748 return;
749 }
Wei Jinf21f0a92014-06-27 17:44:18 -0700750 previous_num_samples_ = strtoul(summary_info[0].c_str(), nullptr, 10);
751 previous_num_null_methods_ = strtoul(summary_info[1].c_str(), nullptr, 10);
752 previous_num_boot_methods_ = strtoul(summary_info[2].c_str(), nullptr, 10);
Dave Allison39c3bfb2014-01-28 18:33:52 -0800753
Wei Jina93b0bb2014-06-09 16:19:15 -0700754 // Now read each line until the end of file. Each line consists of 3 or 4 fields separated by /
Dave Allison39c3bfb2014-01-28 18:33:52 -0800755 while (true) {
756 if (!ReadProfileLine(fd, line)) {
757 break;
758 }
759 std::vector<std::string> info;
760 Split(line, '/', info);
Wei Jina93b0bb2014-06-09 16:19:15 -0700761 if (info.size() != 3 && info.size() != 4) {
Dave Allison39c3bfb2014-01-28 18:33:52 -0800762 // Malformed.
763 break;
764 }
765 std::string methodname = info[0];
Wei Jinf21f0a92014-06-27 17:44:18 -0700766 uint32_t total_count = strtoul(info[1].c_str(), nullptr, 10);
767 uint32_t size = strtoul(info[2].c_str(), nullptr, 10);
Wei Jin445220d2014-06-20 15:56:53 -0700768 PreviousContextMap* context_map = nullptr;
769 if (type == kProfilerBoundedStack && info.size() == 4) {
770 context_map = new PreviousContextMap();
771 std::string context_counts_str = info[3].substr(1, info[3].size() - 2);
772 std::vector<std::string> context_count_pairs;
773 Split(context_counts_str, '#', context_count_pairs);
774 for (uint32_t i = 0; i < context_count_pairs.size(); ++i) {
775 std::vector<std::string> context_count;
776 Split(context_count_pairs[i], ':', context_count);
777 if (context_count.size() == 2) {
778 // Handles the situtation when the profile file doesn't contain context information.
Wei Jinf21f0a92014-06-27 17:44:18 -0700779 uint32_t dexpc = strtoul(context_count[0].c_str(), nullptr, 10);
780 uint32_t count = strtoul(context_count[1].c_str(), nullptr, 10);
Wei Jin445220d2014-06-20 15:56:53 -0700781 (*context_map)[std::make_pair(dexpc, "")] = count;
782 } else {
783 // Handles the situtation when the profile file contains context information.
Wei Jinf21f0a92014-06-27 17:44:18 -0700784 uint32_t dexpc = strtoul(context_count[0].c_str(), nullptr, 10);
785 uint32_t count = strtoul(context_count[1].c_str(), nullptr, 10);
Wei Jin445220d2014-06-20 15:56:53 -0700786 std::string context = context_count[2];
787 (*context_map)[std::make_pair(dexpc, context)] = count;
788 }
Wei Jina93b0bb2014-06-09 16:19:15 -0700789 }
790 }
Wei Jin445220d2014-06-20 15:56:53 -0700791 previous_[methodname] = PreviousValue(total_count, size, context_map);
Dave Allison39c3bfb2014-01-28 18:33:52 -0800792 }
793}
Dave Allison0aded082013-11-07 13:15:11 -0800794
Calin Juravlebb0b53f2014-05-23 17:33:29 +0100795bool ProfileFile::LoadFile(const std::string& fileName) {
Calin Juravle9dae5b42014-04-07 16:36:21 +0300796 LOG(VERBOSE) << "reading profile file " << fileName;
797 struct stat st;
798 int err = stat(fileName.c_str(), &st);
799 if (err == -1) {
800 LOG(VERBOSE) << "not found";
801 return false;
802 }
803 if (st.st_size == 0) {
Dave Allison644789f2014-04-10 13:06:10 -0700804 return false; // Empty profiles are invalid.
Calin Juravle9dae5b42014-04-07 16:36:21 +0300805 }
806 std::ifstream in(fileName.c_str());
807 if (!in) {
808 LOG(VERBOSE) << "profile file " << fileName << " exists but can't be opened";
809 LOG(VERBOSE) << "file owner: " << st.st_uid << ":" << st.st_gid;
810 LOG(VERBOSE) << "me: " << getuid() << ":" << getgid();
811 LOG(VERBOSE) << "file permissions: " << std::oct << st.st_mode;
812 LOG(VERBOSE) << "errno: " << errno;
813 return false;
814 }
815 // The first line contains summary information.
816 std::string line;
817 std::getline(in, line);
818 if (in.eof()) {
819 return false;
820 }
821 std::vector<std::string> summary_info;
822 Split(line, '/', summary_info);
823 if (summary_info.size() != 3) {
Calin Juravle19477a82014-06-06 12:24:21 +0100824 // Bad summary info. It should be total/null/boot.
Calin Juravle9dae5b42014-04-07 16:36:21 +0300825 return false;
826 }
Calin Juravle19477a82014-06-06 12:24:21 +0100827 // This is the number of hits in all profiled methods (without nullptr or boot methods)
Wei Jinf21f0a92014-06-27 17:44:18 -0700828 uint32_t total_count = strtoul(summary_info[0].c_str(), nullptr, 10);
Calin Juravle9dae5b42014-04-07 16:36:21 +0300829
830 // Now read each line until the end of file. Each line consists of 3 fields separated by '/'.
831 // Store the info in descending order given by the most used methods.
832 typedef std::set<std::pair<int, std::vector<std::string>>> ProfileSet;
833 ProfileSet countSet;
834 while (!in.eof()) {
835 std::getline(in, line);
836 if (in.eof()) {
837 break;
838 }
839 std::vector<std::string> info;
840 Split(line, '/', info);
Wei Jina93b0bb2014-06-09 16:19:15 -0700841 if (info.size() != 3 && info.size() != 4) {
Calin Juravle9dae5b42014-04-07 16:36:21 +0300842 // Malformed.
Calin Juravlebb0b53f2014-05-23 17:33:29 +0100843 return false;
Calin Juravle9dae5b42014-04-07 16:36:21 +0300844 }
845 int count = atoi(info[1].c_str());
846 countSet.insert(std::make_pair(-count, info));
847 }
848
849 uint32_t curTotalCount = 0;
850 ProfileSet::iterator end = countSet.end();
851 const ProfileData* prevData = nullptr;
852 for (ProfileSet::iterator it = countSet.begin(); it != end ; it++) {
853 const std::string& methodname = it->second[0];
854 uint32_t count = -it->first;
Wei Jinf21f0a92014-06-27 17:44:18 -0700855 uint32_t size = strtoul(it->second[2].c_str(), nullptr, 10);
Calin Juravle9dae5b42014-04-07 16:36:21 +0300856 double usedPercent = (count * 100.0) / total_count;
857
858 curTotalCount += count;
859 // Methods with the same count should be part of the same top K percentage bucket.
860 double topKPercentage = (prevData != nullptr) && (prevData->GetCount() == count)
861 ? prevData->GetTopKUsedPercentage()
862 : 100 * static_cast<double>(curTotalCount) / static_cast<double>(total_count);
863
864 // Add it to the profile map.
865 ProfileData curData = ProfileData(methodname, count, size, usedPercent, topKPercentage);
Calin Juravlebb0b53f2014-05-23 17:33:29 +0100866 profile_map_[methodname] = curData;
Calin Juravle9dae5b42014-04-07 16:36:21 +0300867 prevData = &curData;
868 }
869 return true;
870}
871
Calin Juravlebb0b53f2014-05-23 17:33:29 +0100872bool ProfileFile::GetProfileData(ProfileFile::ProfileData* data, const std::string& method_name) {
873 ProfileMap::iterator i = profile_map_.find(method_name);
874 if (i == profile_map_.end()) {
Calin Juravle9dae5b42014-04-07 16:36:21 +0300875 return false;
876 }
Calin Juravlebb0b53f2014-05-23 17:33:29 +0100877 *data = i->second;
878 return true;
879}
880
881bool ProfileFile::GetTopKSamples(std::set<std::string>& topKSamples, double topKPercentage) {
882 ProfileMap::iterator end = profile_map_.end();
883 for (ProfileMap::iterator it = profile_map_.begin(); it != end; it++) {
Calin Juravle9dae5b42014-04-07 16:36:21 +0300884 if (it->second.GetTopKUsedPercentage() < topKPercentage) {
885 topKSamples.insert(it->first);
886 }
887 }
888 return true;
889}
890
Wei Jin445220d2014-06-20 15:56:53 -0700891StackTrieNode* StackTrieNode::FindChild(MethodReference method, uint32_t dex_pc) {
892 if (children_.size() == 0) {
893 return nullptr;
894 }
895 // Create a dummy node for searching.
896 StackTrieNode* node = new StackTrieNode(method, dex_pc, 0, nullptr);
897 std::set<StackTrieNode*, StackTrieNodeComparator>::iterator i = children_.find(node);
898 delete node;
899 return (i == children_.end()) ? nullptr : *i;
900}
901
902void StackTrieNode::DeleteChildren() {
903 for (auto &child : children_) {
904 if (child != nullptr) {
905 child->DeleteChildren();
906 delete child;
907 }
908 }
909}
910
Calin Juravle9dae5b42014-04-07 16:36:21 +0300911} // namespace art