1 /*
2 * Copyright (C) 2015 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 "profile_saver.h"
18
19 #include <fcntl.h>
20 #include <sys/resource.h>
21 #include <sys/stat.h>
22 #include <sys/types.h>
23
24 #include "android-base/strings.h"
25
26 #include "art_method-inl.h"
27 #include "base/enums.h"
28 #include "base/logging.h" // For VLOG.
29 #include "base/scoped_arena_containers.h"
30 #include "base/stl_util.h"
31 #include "base/systrace.h"
32 #include "base/time_utils.h"
33 #include "class_table-inl.h"
34 #include "compiler_filter.h"
35 #include "dex/dex_file_loader.h"
36 #include "dex_reference_collection.h"
37 #include "gc/collector_type.h"
38 #include "gc/gc_cause.h"
39 #include "gc/scoped_gc_critical_section.h"
40 #include "jit/profiling_info.h"
41 #include "oat_file_manager.h"
42 #include "profile/profile_compilation_info.h"
43 #include "scoped_thread_state_change-inl.h"
44
45 namespace art {
46
47 ProfileSaver* ProfileSaver::instance_ = nullptr;
48 pthread_t ProfileSaver::profiler_pthread_ = 0U;
49
50 static_assert(ProfileCompilationInfo::kIndividualInlineCacheSize ==
51 InlineCache::kIndividualCacheSize,
52 "InlineCache and ProfileCompilationInfo do not agree on kIndividualCacheSize");
53
54 // At what priority to schedule the saver threads. 9 is the lowest foreground priority on device.
55 static constexpr int kProfileSaverPthreadPriority = 9;
56
SetProfileSaverThreadPriority(pthread_t thread,int priority)57 static void SetProfileSaverThreadPriority(pthread_t thread, int priority) {
58 #if defined(ART_TARGET_ANDROID)
59 int result = setpriority(PRIO_PROCESS, pthread_gettid_np(thread), priority);
60 if (result != 0) {
61 LOG(ERROR) << "Failed to setpriority to :" << priority;
62 }
63 #else
64 UNUSED(thread);
65 UNUSED(priority);
66 #endif
67 }
68
GetDefaultThreadPriority()69 static int GetDefaultThreadPriority() {
70 #if defined(ART_TARGET_ANDROID)
71 pthread_attr_t attr;
72 sched_param param;
73 pthread_attr_init(&attr);
74 pthread_attr_getschedparam(&attr, ¶m);
75 return param.sched_priority;
76 #else
77 return 0;
78 #endif
79 }
80
ProfileSaver(const ProfileSaverOptions & options,const std::string & output_filename,jit::JitCodeCache * jit_code_cache,const std::vector<std::string> & code_paths)81 ProfileSaver::ProfileSaver(const ProfileSaverOptions& options,
82 const std::string& output_filename,
83 jit::JitCodeCache* jit_code_cache,
84 const std::vector<std::string>& code_paths)
85 : jit_code_cache_(jit_code_cache),
86 shutting_down_(false),
87 last_time_ns_saver_woke_up_(0),
88 jit_activity_notifications_(0),
89 wait_lock_("ProfileSaver wait lock"),
90 period_condition_("ProfileSaver period condition", wait_lock_),
91 total_bytes_written_(0),
92 total_number_of_writes_(0),
93 total_number_of_code_cache_queries_(0),
94 total_number_of_skipped_writes_(0),
95 total_number_of_failed_writes_(0),
96 total_ms_of_sleep_(0),
97 total_ns_of_work_(0),
98 max_number_of_profile_entries_cached_(0),
99 total_number_of_hot_spikes_(0),
100 total_number_of_wake_ups_(0),
101 options_(options) {
102 DCHECK(options_.IsEnabled());
103 AddTrackedLocations(output_filename, code_paths);
104 }
105
~ProfileSaver()106 ProfileSaver::~ProfileSaver() {
107 for (auto& it : profile_cache_) {
108 delete it.second;
109 }
110 }
111
NotifyStartupCompleted()112 void ProfileSaver::NotifyStartupCompleted() {
113 Thread* self = Thread::Current();
114 MutexLock mu(self, *Locks::profiler_lock_);
115 if (instance_ == nullptr || instance_->shutting_down_) {
116 return;
117 }
118 MutexLock mu2(self, instance_->wait_lock_);
119 instance_->period_condition_.Signal(self);
120 }
121
Run()122 void ProfileSaver::Run() {
123 Thread* self = Thread::Current();
124
125 // Fetch the resolved classes for the app images after sleeping for
126 // options_.GetSaveResolvedClassesDelayMs().
127 // TODO(calin) This only considers the case of the primary profile file.
128 // Anything that gets loaded in the same VM will not have their resolved
129 // classes save (unless they started before the initial saving was done).
130 {
131 MutexLock mu(self, wait_lock_);
132 const uint64_t end_time = NanoTime() + MsToNs(options_.GetSaveResolvedClassesDelayMs());
133 while (!Runtime::Current()->GetStartupCompleted()) {
134 const uint64_t current_time = NanoTime();
135 if (current_time >= end_time) {
136 break;
137 }
138 period_condition_.TimedWait(self, NsToMs(end_time - current_time), 0);
139 }
140 total_ms_of_sleep_ += options_.GetSaveResolvedClassesDelayMs();
141 }
142 // Tell the runtime that startup is completed if it has not already been notified.
143 // TODO: We should use another thread to do this in case the profile saver is not running.
144 Runtime::Current()->NotifyStartupCompleted();
145
146 FetchAndCacheResolvedClassesAndMethods(/*startup=*/ true);
147
148 // When we save without waiting for JIT notifications we use a simple
149 // exponential back off policy bounded by max_wait_without_jit.
150 uint32_t max_wait_without_jit = options_.GetMinSavePeriodMs() * 16;
151 uint64_t cur_wait_without_jit = options_.GetMinSavePeriodMs();
152 // Loop for the profiled methods.
153 while (!ShuttingDown(self)) {
154 uint64_t sleep_start = NanoTime();
155 {
156 uint64_t sleep_time = 0;
157 {
158 MutexLock mu(self, wait_lock_);
159 if (options_.GetWaitForJitNotificationsToSave()) {
160 period_condition_.Wait(self);
161 } else {
162 period_condition_.TimedWait(self, cur_wait_without_jit, 0);
163 if (cur_wait_without_jit < max_wait_without_jit) {
164 cur_wait_without_jit *= 2;
165 }
166 }
167 sleep_time = NanoTime() - sleep_start;
168 }
169 // Check if the thread was woken up for shutdown.
170 if (ShuttingDown(self)) {
171 break;
172 }
173 total_number_of_wake_ups_++;
174 // We might have been woken up by a huge number of notifications to guarantee saving.
175 // If we didn't meet the minimum saving period go back to sleep (only if missed by
176 // a reasonable margin).
177 uint64_t min_save_period_ns = MsToNs(options_.GetMinSavePeriodMs());
178 while (min_save_period_ns * 0.9 > sleep_time) {
179 {
180 MutexLock mu(self, wait_lock_);
181 period_condition_.TimedWait(self, NsToMs(min_save_period_ns - sleep_time), 0);
182 sleep_time = NanoTime() - sleep_start;
183 }
184 // Check if the thread was woken up for shutdown.
185 if (ShuttingDown(self)) {
186 break;
187 }
188 total_number_of_wake_ups_++;
189 }
190 }
191 total_ms_of_sleep_ += NsToMs(NanoTime() - sleep_start);
192
193 if (ShuttingDown(self)) {
194 break;
195 }
196
197 uint16_t number_of_new_methods = 0;
198 uint64_t start_work = NanoTime();
199 bool profile_saved_to_disk = ProcessProfilingInfo(/*force_save=*/false, &number_of_new_methods);
200 // Update the notification counter based on result. Note that there might be contention on this
201 // but we don't care about to be 100% precise.
202 if (!profile_saved_to_disk) {
203 // If we didn't save to disk it may be because we didn't have enough new methods.
204 // Set the jit activity notifications to number_of_new_methods so we can wake up earlier
205 // if needed.
206 jit_activity_notifications_ = number_of_new_methods;
207 }
208 total_ns_of_work_ += NanoTime() - start_work;
209 }
210 }
211
NotifyJitActivity()212 void ProfileSaver::NotifyJitActivity() {
213 MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
214 if (instance_ == nullptr || instance_->shutting_down_) {
215 return;
216 }
217 instance_->NotifyJitActivityInternal();
218 }
219
WakeUpSaver()220 void ProfileSaver::WakeUpSaver() {
221 jit_activity_notifications_ = 0;
222 last_time_ns_saver_woke_up_ = NanoTime();
223 period_condition_.Signal(Thread::Current());
224 }
225
NotifyJitActivityInternal()226 void ProfileSaver::NotifyJitActivityInternal() {
227 // Unlikely to overflow but if it happens,
228 // we would have waken up the saver long before that.
229 jit_activity_notifications_++;
230 // Note that we are not as precise as we could be here but we don't want to wake the saver
231 // every time we see a hot method.
232 if (jit_activity_notifications_ > options_.GetMinNotificationBeforeWake()) {
233 MutexLock wait_mutex(Thread::Current(), wait_lock_);
234 if ((NanoTime() - last_time_ns_saver_woke_up_) > MsToNs(options_.GetMinSavePeriodMs())) {
235 WakeUpSaver();
236 } else if (jit_activity_notifications_ > options_.GetMaxNotificationBeforeWake()) {
237 // Make sure to wake up the saver if we see a spike in the number of notifications.
238 // This is a precaution to avoid losing a big number of methods in case
239 // this is a spike with no jit after.
240 total_number_of_hot_spikes_++;
241 WakeUpSaver();
242 }
243 }
244 }
245
246 class ScopedDefaultPriority {
247 public:
ScopedDefaultPriority(pthread_t thread)248 explicit ScopedDefaultPriority(pthread_t thread) : thread_(thread) {
249 SetProfileSaverThreadPriority(thread_, GetDefaultThreadPriority());
250 }
251
~ScopedDefaultPriority()252 ~ScopedDefaultPriority() {
253 SetProfileSaverThreadPriority(thread_, kProfileSaverPthreadPriority);
254 }
255
256 private:
257 const pthread_t thread_;
258 };
259
260 // GetClassLoadersVisitor takes a snapshot of the class loaders and stores them in the out
261 // class_loaders argument. Not affected by class unloading since there are no suspend points in
262 // the caller.
263 class GetClassLoadersVisitor : public ClassLoaderVisitor {
264 public:
GetClassLoadersVisitor(VariableSizedHandleScope * hs,std::vector<Handle<mirror::ClassLoader>> * class_loaders)265 explicit GetClassLoadersVisitor(VariableSizedHandleScope* hs,
266 std::vector<Handle<mirror::ClassLoader>>* class_loaders)
267 : hs_(hs),
268 class_loaders_(class_loaders) {}
269
Visit(ObjPtr<mirror::ClassLoader> class_loader)270 void Visit(ObjPtr<mirror::ClassLoader> class_loader)
271 REQUIRES_SHARED(Locks::classlinker_classes_lock_, Locks::mutator_lock_) override {
272 class_loaders_->push_back(hs_->NewHandle(class_loader));
273 }
274
275 private:
276 VariableSizedHandleScope* const hs_;
277 std::vector<Handle<mirror::ClassLoader>>* const class_loaders_;
278 };
279
280 // GetClassesVisitor takes a snapshot of the loaded classes that we may want to visit and stores
281 // them in the out argument. Not affected by class unloading since there are no suspend points in
282 // the caller.
283 class GetClassesVisitor : public ClassVisitor {
284 public:
GetClassesVisitor(bool profile_boot_class_path,ScopedArenaVector<ObjPtr<mirror::Class>> * out)285 explicit GetClassesVisitor(bool profile_boot_class_path,
286 ScopedArenaVector<ObjPtr<mirror::Class>>* out)
287 : profile_boot_class_path_(profile_boot_class_path),
288 out_(out) {}
289
operator ()(ObjPtr<mirror::Class> klass)290 bool operator()(ObjPtr<mirror::Class> klass) override REQUIRES_SHARED(Locks::mutator_lock_) {
291 if (klass->IsProxyClass() ||
292 klass->IsArrayClass() ||
293 klass->IsPrimitive() ||
294 !klass->IsResolved() ||
295 klass->IsErroneousResolved() ||
296 (!profile_boot_class_path_ && klass->GetClassLoader() == nullptr)) {
297 return true;
298 }
299 out_->push_back(klass);
300 return true;
301 }
302
303 private:
304 const bool profile_boot_class_path_;
305 ScopedArenaVector<ObjPtr<mirror::Class>>* const out_;
306 };
307
308 using MethodReferenceCollection = DexReferenceCollection<uint16_t, ScopedArenaAllocatorAdapter>;
309 using TypeReferenceCollection = DexReferenceCollection<dex::TypeIndex,
310 ScopedArenaAllocatorAdapter>;
311
312 // Iterate over all of the loaded classes and visit each one. For each class, add it to the
313 // resolved_classes out argument if startup is true.
314 // Add methods to the hot_methods out argument if the number of samples is greater or equal to
315 // hot_method_sample_threshold, add it to sampled_methods if it has at least one sample.
SampleClassesAndExecutedMethods(pthread_t profiler_pthread,bool profile_boot_class_path,ScopedArenaAllocator * allocator,uint32_t hot_method_sample_threshold,bool startup,TypeReferenceCollection * resolved_classes,MethodReferenceCollection * hot_methods,MethodReferenceCollection * sampled_methods)316 static void SampleClassesAndExecutedMethods(pthread_t profiler_pthread,
317 bool profile_boot_class_path,
318 ScopedArenaAllocator* allocator,
319 uint32_t hot_method_sample_threshold,
320 bool startup,
321 TypeReferenceCollection* resolved_classes,
322 MethodReferenceCollection* hot_methods,
323 MethodReferenceCollection* sampled_methods) {
324 Thread* const self = Thread::Current();
325 ClassLinker* const class_linker = Runtime::Current()->GetClassLinker();
326 // Restore profile saver thread priority during the GC critical section. This helps prevent
327 // priority inversions blocking the GC for long periods of time.
328 std::unique_ptr<ScopedDefaultPriority> sdp;
329 // Only restore default priority if we are the profile saver thread. Other threads that call this
330 // are threads calling Stop and the signal catcher (for SIGUSR1).
331 if (pthread_self() == profiler_pthread) {
332 sdp.reset(new ScopedDefaultPriority(profiler_pthread));
333 }
334
335 // Do ScopedGCCriticalSection before acquiring mutator lock to prevent the GC running and
336 // blocking threads during thread root flipping. Since the GC is a background thread, blocking it
337 // is not a problem.
338 ScopedObjectAccess soa(self);
339 gc::ScopedGCCriticalSection sgcs(self,
340 gc::kGcCauseProfileSaver,
341 gc::kCollectorTypeCriticalSection);
342 VariableSizedHandleScope hs(soa.Self());
343 std::vector<Handle<mirror::ClassLoader>> class_loaders;
344 if (profile_boot_class_path) {
345 // First add the boot class loader since visit classloaders doesn't visit it.
346 class_loaders.push_back(hs.NewHandle<mirror::ClassLoader>(nullptr));
347 }
348 GetClassLoadersVisitor class_loader_visitor(&hs, &class_loaders);
349 {
350 // Read the class loaders into a temporary array to prevent contention problems on the
351 // class_linker_classes_lock.
352 ScopedTrace trace2("Get class loaders");
353 ReaderMutexLock mu(soa.Self(), *Locks::classlinker_classes_lock_);
354 class_linker->VisitClassLoaders(&class_loader_visitor);
355 }
356 ScopedArenaVector<ObjPtr<mirror::Class>> classes(allocator->Adapter());
357 for (Handle<mirror::ClassLoader> class_loader : class_loaders) {
358 ClassTable* table = class_linker->ClassTableForClassLoader(class_loader.Get());
359 if (table == nullptr) {
360 // If the class loader has not loaded any classes, it may have a null table.
361 continue;
362 }
363 GetClassesVisitor get_classes_visitor(profile_boot_class_path, &classes);
364 {
365 // Collect the classes into a temporary array to prevent lock contention on the class
366 // table lock. We want to avoid blocking class loading in other threads as much as
367 // possible.
368 ScopedTrace trace3("Visiting class table");
369 table->Visit(get_classes_visitor);
370 }
371 for (ObjPtr<mirror::Class> klass : classes) {
372 if (startup) {
373 // We only record classes for the startup case. This may change in the future.
374 resolved_classes->AddReference(&klass->GetDexFile(), klass->GetDexTypeIndex());
375 }
376 // Visit all of the methods in the class to see which ones were executed.
377 for (ArtMethod& method : klass->GetMethods(kRuntimePointerSize)) {
378 if (!method.IsNative() && !method.IsAbstract()) {
379 DCHECK(!method.IsProxyMethod());
380 const uint16_t counter = method.GetCounter();
381 // Mark startup methods as hot if they have more than hot_method_sample_threshold
382 // samples. This means they will get compiled by the compiler driver.
383 if (method.GetProfilingInfo(kRuntimePointerSize) != nullptr ||
384 method.PreviouslyWarm() ||
385 counter >= hot_method_sample_threshold) {
386 hot_methods->AddReference(method.GetDexFile(), method.GetDexMethodIndex());
387 } else if (counter != 0) {
388 sampled_methods->AddReference(method.GetDexFile(), method.GetDexMethodIndex());
389 }
390 } else {
391 // We do not record native methods. Once we AOT-compile the app, all native
392 // methods shall have their thunks compiled.
393 }
394 }
395 }
396 classes.clear();
397 }
398 }
399
FetchAndCacheResolvedClassesAndMethods(bool startup)400 void ProfileSaver::FetchAndCacheResolvedClassesAndMethods(bool startup) {
401 ScopedTrace trace(__PRETTY_FUNCTION__);
402 const uint64_t start_time = NanoTime();
403
404 // Resolve any new registered locations.
405 ResolveTrackedLocations();
406
407 Thread* const self = Thread::Current();
408 Runtime* const runtime = Runtime::Current();
409 ArenaStack stack(runtime->GetArenaPool());
410 ScopedArenaAllocator allocator(&stack);
411 MethodReferenceCollection hot_methods(allocator.Adapter(), allocator.Adapter());
412 MethodReferenceCollection sampled_methods(allocator.Adapter(), allocator.Adapter());
413 TypeReferenceCollection resolved_classes(allocator.Adapter(), allocator.Adapter());
414 const bool is_low_ram = Runtime::Current()->GetHeap()->IsLowMemoryMode();
415 pthread_t profiler_pthread;
416 {
417 MutexLock mu(self, *Locks::profiler_lock_);
418 profiler_pthread = profiler_pthread_;
419 }
420 const uint32_t hot_method_sample_threshold = startup ?
421 options_.GetHotStartupMethodSamples(is_low_ram) :
422 std::numeric_limits<uint32_t>::max();
423 SampleClassesAndExecutedMethods(profiler_pthread,
424 options_.GetProfileBootClassPath(),
425 &allocator,
426 hot_method_sample_threshold,
427 startup,
428 &resolved_classes,
429 &hot_methods,
430 &sampled_methods);
431 MutexLock mu(self, *Locks::profiler_lock_);
432 uint64_t total_number_of_profile_entries_cached = 0;
433 using Hotness = ProfileCompilationInfo::MethodHotness;
434
435 for (const auto& it : tracked_dex_base_locations_) {
436 std::set<DexCacheResolvedClasses> resolved_classes_for_location;
437 const std::string& filename = it.first;
438 auto info_it = profile_cache_.find(filename);
439 if (info_it == profile_cache_.end()) {
440 info_it = profile_cache_.Put(
441 filename,
442 new ProfileCompilationInfo(Runtime::Current()->GetArenaPool()));
443 }
444 ProfileCompilationInfo* cached_info = info_it->second;
445
446 const std::set<std::string>& locations = it.second;
447 VLOG(profiler) << "Locations for " << it.first << " " << android::base::Join(locations, ':');
448
449 for (const auto& pair : hot_methods.GetMap()) {
450 const DexFile* const dex_file = pair.first;
451 const std::string base_location = DexFileLoader::GetBaseLocation(dex_file->GetLocation());
452 const MethodReferenceCollection::IndexVector& indices = pair.second;
453 VLOG(profiler) << "Location " << dex_file->GetLocation()
454 << " base_location=" << base_location
455 << " found=" << (locations.find(base_location) != locations.end())
456 << " indices size=" << indices.size();
457 if (locations.find(base_location) != locations.end()) {
458 uint8_t flags = Hotness::kFlagHot;
459 flags |= startup ? Hotness::kFlagStartup : Hotness::kFlagPostStartup;
460 cached_info->AddMethodsForDex(
461 static_cast<Hotness::Flag>(flags),
462 dex_file,
463 indices.begin(),
464 indices.end());
465 }
466 }
467 for (const auto& pair : sampled_methods.GetMap()) {
468 const DexFile* const dex_file = pair.first;
469 const std::string base_location = DexFileLoader::GetBaseLocation(dex_file->GetLocation());
470 const MethodReferenceCollection::IndexVector& indices = pair.second;
471 VLOG(profiler) << "Location " << base_location
472 << " found=" << (locations.find(base_location) != locations.end())
473 << " indices size=" << indices.size();
474 if (locations.find(base_location) != locations.end()) {
475 cached_info->AddMethodsForDex(startup ? Hotness::kFlagStartup : Hotness::kFlagPostStartup,
476 dex_file,
477 indices.begin(),
478 indices.end());
479 }
480 }
481 for (const auto& pair : resolved_classes.GetMap()) {
482 const DexFile* const dex_file = pair.first;
483 const std::string base_location = DexFileLoader::GetBaseLocation(dex_file->GetLocation());
484 if (locations.find(base_location) != locations.end()) {
485 const TypeReferenceCollection::IndexVector& classes = pair.second;
486 VLOG(profiler) << "Added " << classes.size() << " classes for location "
487 << base_location
488 << " (" << dex_file->GetLocation() << ")";
489 cached_info->AddClassesForDex(dex_file, classes.begin(), classes.end());
490 } else {
491 VLOG(profiler) << "Location not found " << base_location;
492 }
493 }
494 total_number_of_profile_entries_cached += resolved_classes_for_location.size();
495 }
496 max_number_of_profile_entries_cached_ = std::max(
497 max_number_of_profile_entries_cached_,
498 total_number_of_profile_entries_cached);
499 VLOG(profiler) << "Profile saver recorded " << hot_methods.NumReferences() << " hot methods and "
500 << sampled_methods.NumReferences() << " sampled methods with threshold "
501 << hot_method_sample_threshold << " in "
502 << PrettyDuration(NanoTime() - start_time);
503 }
504
ProcessProfilingInfo(bool force_save,uint16_t * number_of_new_methods)505 bool ProfileSaver::ProcessProfilingInfo(bool force_save, /*out*/uint16_t* number_of_new_methods) {
506 ScopedTrace trace(__PRETTY_FUNCTION__);
507
508 // Resolve any new registered locations.
509 ResolveTrackedLocations();
510
511 SafeMap<std::string, std::set<std::string>> tracked_locations;
512 {
513 // Make a copy so that we don't hold the lock while doing I/O.
514 MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
515 tracked_locations = tracked_dex_base_locations_;
516 }
517
518 bool profile_file_saved = false;
519 if (number_of_new_methods != nullptr) {
520 *number_of_new_methods = 0;
521 }
522
523 // We only need to do this once, not once per dex location.
524 // TODO: Figure out a way to only do it when stuff has changed? It takes 30-50ms.
525 FetchAndCacheResolvedClassesAndMethods(/*startup=*/ false);
526
527 for (const auto& it : tracked_locations) {
528 if (!force_save && ShuttingDown(Thread::Current())) {
529 // The ProfileSaver is in shutdown mode, meaning a stop request was made and
530 // we need to exit cleanly (by waiting for the saver thread to finish). Unless
531 // we have a request for a forced save, do not do any processing so that we
532 // speed up the exit.
533 return true;
534 }
535 const std::string& filename = it.first;
536 const std::set<std::string>& locations = it.second;
537 VLOG(profiler) << "Tracked filename " << filename << " locations "
538 << android::base::Join(locations, ":");
539
540 std::vector<ProfileMethodInfo> profile_methods;
541 {
542 ScopedObjectAccess soa(Thread::Current());
543 jit_code_cache_->GetProfiledMethods(locations, profile_methods);
544 total_number_of_code_cache_queries_++;
545 }
546 {
547 ProfileCompilationInfo info(Runtime::Current()->GetArenaPool());
548 if (!info.Load(filename, /*clear_if_invalid=*/ true)) {
549 LOG(WARNING) << "Could not forcefully load profile " << filename;
550 continue;
551 }
552 uint64_t last_save_number_of_methods = info.GetNumberOfMethods();
553 uint64_t last_save_number_of_classes = info.GetNumberOfResolvedClasses();
554 VLOG(profiler) << "last_save_number_of_methods=" << last_save_number_of_methods
555 << " last_save_number_of_classes=" << last_save_number_of_classes
556 << " number of profiled methods=" << profile_methods.size();
557
558 // Try to add the method data. Note this may fail is the profile loaded from disk contains
559 // outdated data (e.g. the previous profiled dex files might have been updated).
560 // If this happens we clear the profile data and for the save to ensure the file is cleared.
561 if (!info.AddMethods(profile_methods,
562 ProfileCompilationInfo::MethodHotness::kFlagPostStartup)) {
563 LOG(WARNING) << "Could not add methods to the existing profiler. "
564 << "Clearing the profile data.";
565 info.ClearData();
566 force_save = true;
567 }
568
569 auto profile_cache_it = profile_cache_.find(filename);
570 if (profile_cache_it != profile_cache_.end()) {
571 if (!info.MergeWith(*(profile_cache_it->second))) {
572 LOG(WARNING) << "Could not merge the profile. Clearing the profile data.";
573 info.ClearData();
574 force_save = true;
575 }
576 } else if (VLOG_IS_ON(profiler)) {
577 LOG(INFO) << "Failed to find cached profile for " << filename;
578 for (auto&& pair : profile_cache_) {
579 LOG(INFO) << "Cached profile " << pair.first;
580 }
581 }
582
583 int64_t delta_number_of_methods =
584 info.GetNumberOfMethods() - last_save_number_of_methods;
585 int64_t delta_number_of_classes =
586 info.GetNumberOfResolvedClasses() - last_save_number_of_classes;
587
588 if (!force_save &&
589 delta_number_of_methods < options_.GetMinMethodsToSave() &&
590 delta_number_of_classes < options_.GetMinClassesToSave()) {
591 VLOG(profiler) << "Not enough information to save to: " << filename
592 << " Number of methods: " << delta_number_of_methods
593 << " Number of classes: " << delta_number_of_classes;
594 total_number_of_skipped_writes_++;
595 continue;
596 }
597
598 if (number_of_new_methods != nullptr) {
599 *number_of_new_methods =
600 std::max(static_cast<uint16_t>(delta_number_of_methods),
601 *number_of_new_methods);
602 }
603 uint64_t bytes_written;
604 // Force the save. In case the profile data is corrupted or the the profile
605 // has the wrong version this will "fix" the file to the correct format.
606 if (info.Save(filename, &bytes_written)) {
607 // We managed to save the profile. Clear the cache stored during startup.
608 if (profile_cache_it != profile_cache_.end()) {
609 ProfileCompilationInfo *cached_info = profile_cache_it->second;
610 profile_cache_.erase(profile_cache_it);
611 delete cached_info;
612 }
613 if (bytes_written > 0) {
614 total_number_of_writes_++;
615 total_bytes_written_ += bytes_written;
616 profile_file_saved = true;
617 } else {
618 // At this point we could still have avoided the write.
619 // We load and merge the data from the file lazily at its first ever
620 // save attempt. So, whatever we are trying to save could already be
621 // in the file.
622 total_number_of_skipped_writes_++;
623 }
624 } else {
625 LOG(WARNING) << "Could not save profiling info to " << filename;
626 total_number_of_failed_writes_++;
627 }
628 }
629 }
630
631 // Trim the maps to madvise the pages used for profile info.
632 // It is unlikely we will need them again in the near feature.
633 Runtime::Current()->GetArenaPool()->TrimMaps();
634
635 return profile_file_saved;
636 }
637
RunProfileSaverThread(void * arg)638 void* ProfileSaver::RunProfileSaverThread(void* arg) {
639 Runtime* runtime = Runtime::Current();
640
641 bool attached = runtime->AttachCurrentThread("Profile Saver",
642 /*as_daemon=*/true,
643 runtime->GetSystemThreadGroup(),
644 /*create_peer=*/true);
645 if (!attached) {
646 CHECK(runtime->IsShuttingDown(Thread::Current()));
647 return nullptr;
648 }
649
650 ProfileSaver* profile_saver = reinterpret_cast<ProfileSaver*>(arg);
651 profile_saver->Run();
652
653 runtime->DetachCurrentThread();
654 VLOG(profiler) << "Profile saver shutdown";
655 return nullptr;
656 }
657
ShouldProfileLocation(const std::string & location,bool profile_aot_code)658 static bool ShouldProfileLocation(const std::string& location, bool profile_aot_code) {
659 if (profile_aot_code) {
660 // If we have to profile all the code, irrespective of its compilation state, return true
661 // right away.
662 return true;
663 }
664
665 OatFileManager& oat_manager = Runtime::Current()->GetOatFileManager();
666 const OatFile* oat_file = oat_manager.FindOpenedOatFileFromDexLocation(location);
667 if (oat_file == nullptr) {
668 // This can happen if we fallback to run code directly from the APK.
669 // Profile it with the hope that the background dexopt will get us back into
670 // a good state.
671 VLOG(profiler) << "Asked to profile a location without an oat file:" << location;
672 return true;
673 }
674 CompilerFilter::Filter filter = oat_file->GetCompilerFilter();
675 if ((filter == CompilerFilter::kSpeed) || (filter == CompilerFilter::kEverything)) {
676 VLOG(profiler)
677 << "Skip profiling oat file because it's already speed|everything compiled: "
678 << location << " oat location: " << oat_file->GetLocation();
679 return false;
680 }
681 return true;
682 }
683
Start(const ProfileSaverOptions & options,const std::string & output_filename,jit::JitCodeCache * jit_code_cache,const std::vector<std::string> & code_paths)684 void ProfileSaver::Start(const ProfileSaverOptions& options,
685 const std::string& output_filename,
686 jit::JitCodeCache* jit_code_cache,
687 const std::vector<std::string>& code_paths) {
688 Runtime* const runtime = Runtime::Current();
689 DCHECK(options.IsEnabled());
690 DCHECK(runtime->GetJit() != nullptr);
691 DCHECK(!output_filename.empty());
692 DCHECK(jit_code_cache != nullptr);
693
694 std::vector<std::string> code_paths_to_profile;
695 for (const std::string& location : code_paths) {
696 if (ShouldProfileLocation(location, options.GetProfileAOTCode())) {
697 VLOG(profiler) << "Code path to profile " << location;
698 code_paths_to_profile.push_back(location);
699 }
700 }
701
702 MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
703 // Support getting profile samples for the boot class path. This will be used to generate the boot
704 // image profile. The intention is to use this code to generate to boot image but not use it in
705 // production. b/37966211
706 if (options.GetProfileBootClassPath()) {
707 std::set<std::string> code_paths_keys;
708 for (const std::string& location : code_paths) {
709 code_paths_keys.insert(ProfileCompilationInfo::GetProfileDexFileKey(location));
710 }
711 for (const DexFile* dex_file : runtime->GetClassLinker()->GetBootClassPath()) {
712 // Don't check ShouldProfileLocation since the boot class path may be speed compiled.
713 const std::string& location = dex_file->GetLocation();
714 const std::string key = ProfileCompilationInfo::GetProfileDexFileKey(location);
715 VLOG(profiler) << "Registering boot dex file " << location;
716 if (code_paths_keys.find(key) != code_paths_keys.end()) {
717 LOG(WARNING) << "Boot class path location key conflicts with code path " << location;
718 } else if (instance_ == nullptr) {
719 // Only add the boot class path once since Start may be called multiple times for secondary
720 // dexes.
721 // We still do the collision check above. This handles any secondary dexes that conflict
722 // with the boot class path dex files.
723 code_paths_to_profile.push_back(location);
724 }
725 }
726 }
727 if (code_paths_to_profile.empty()) {
728 VLOG(profiler) << "No code paths should be profiled.";
729 return;
730 }
731
732 if (instance_ != nullptr) {
733 // If we already have an instance, make sure it uses the same jit_code_cache.
734 // This may be called multiple times via Runtime::registerAppInfo (e.g. for
735 // apps which share the same runtime).
736 DCHECK_EQ(instance_->jit_code_cache_, jit_code_cache);
737 // Add the code_paths to the tracked locations.
738 instance_->AddTrackedLocations(output_filename, code_paths_to_profile);
739 return;
740 }
741
742 VLOG(profiler) << "Starting profile saver using output file: " << output_filename
743 << ". Tracking: " << android::base::Join(code_paths_to_profile, ':');
744
745 instance_ = new ProfileSaver(options,
746 output_filename,
747 jit_code_cache,
748 code_paths_to_profile);
749
750 // Create a new thread which does the saving.
751 CHECK_PTHREAD_CALL(
752 pthread_create,
753 (&profiler_pthread_, nullptr, &RunProfileSaverThread, reinterpret_cast<void*>(instance_)),
754 "Profile saver thread");
755
756 SetProfileSaverThreadPriority(profiler_pthread_, kProfileSaverPthreadPriority);
757 }
758
Stop(bool dump_info)759 void ProfileSaver::Stop(bool dump_info) {
760 ProfileSaver* profile_saver = nullptr;
761 pthread_t profiler_pthread = 0U;
762
763 {
764 MutexLock profiler_mutex(Thread::Current(), *Locks::profiler_lock_);
765 VLOG(profiler) << "Stopping profile saver thread";
766 profile_saver = instance_;
767 profiler_pthread = profiler_pthread_;
768 if (instance_ == nullptr) {
769 DCHECK(false) << "Tried to stop a profile saver which was not started";
770 return;
771 }
772 if (instance_->shutting_down_) {
773 DCHECK(false) << "Tried to stop the profile saver twice";
774 return;
775 }
776 instance_->shutting_down_ = true;
777 }
778
779 {
780 // Wake up the saver thread if it is sleeping to allow for a clean exit.
781 MutexLock wait_mutex(Thread::Current(), profile_saver->wait_lock_);
782 profile_saver->period_condition_.Signal(Thread::Current());
783 }
784
785 // Force save everything before destroying the thread since we want profiler_pthread_ to remain
786 // valid.
787 instance_->ProcessProfilingInfo(/*force_save=*/true, /*number_of_new_methods=*/nullptr);
788
789 // Wait for the saver thread to stop.
790 CHECK_PTHREAD_CALL(pthread_join, (profiler_pthread, nullptr), "profile saver thread shutdown");
791
792 {
793 MutexLock profiler_mutex(Thread::Current(), *Locks::profiler_lock_);
794 if (dump_info) {
795 instance_->DumpInfo(LOG_STREAM(INFO));
796 }
797 instance_ = nullptr;
798 profiler_pthread_ = 0U;
799 }
800 delete profile_saver;
801 }
802
ShuttingDown(Thread * self)803 bool ProfileSaver::ShuttingDown(Thread* self) {
804 MutexLock mu(self, *Locks::profiler_lock_);
805 return shutting_down_;
806 }
807
IsStarted()808 bool ProfileSaver::IsStarted() {
809 MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
810 return instance_ != nullptr;
811 }
812
AddTrackedLocationsToMap(const std::string & output_filename,const std::vector<std::string> & code_paths,SafeMap<std::string,std::set<std::string>> * map)813 static void AddTrackedLocationsToMap(const std::string& output_filename,
814 const std::vector<std::string>& code_paths,
815 SafeMap<std::string, std::set<std::string>>* map) {
816 std::vector<std::string> code_paths_and_filenames;
817 // The dex locations are sometimes set to the filename instead of the full path.
818 // So make sure we have both "locations" when tracking what needs to be profiled.
819 // - apps + system server have filenames
820 // - boot classpath elements have full paths
821
822 // TODO(calin, ngeoffray, vmarko) This is an workaround for using filanames as
823 // dex locations - needed to prebuilt with a partial boot image
824 // (commit: c4a924d8c74241057d957d360bf31cd5cd0e4f9c).
825 // We should find a better way which allows us to do the tracking based on full paths.
826 for (const std::string& path : code_paths) {
827 size_t last_sep_index = path.find_last_of('/');
828 if (last_sep_index == path.size() - 1) {
829 // Should not happen, but anyone can register code paths so better be prepared and ignore
830 // such locations.
831 continue;
832 }
833 std::string filename = last_sep_index == std::string::npos
834 ? path
835 : path.substr(last_sep_index + 1);
836
837 code_paths_and_filenames.push_back(path);
838 code_paths_and_filenames.push_back(filename);
839 }
840
841 auto it = map->find(output_filename);
842 if (it == map->end()) {
843 map->Put(
844 output_filename,
845 std::set<std::string>(code_paths_and_filenames.begin(), code_paths_and_filenames.end()));
846 } else {
847 it->second.insert(code_paths_and_filenames.begin(), code_paths_and_filenames.end());
848 }
849 }
850
AddTrackedLocations(const std::string & output_filename,const std::vector<std::string> & code_paths)851 void ProfileSaver::AddTrackedLocations(const std::string& output_filename,
852 const std::vector<std::string>& code_paths) {
853 // Add the code paths to the list of tracked location.
854 AddTrackedLocationsToMap(output_filename, code_paths, &tracked_dex_base_locations_);
855 // The code paths may contain symlinks which could fool the profiler.
856 // If the dex file is compiled with an absolute location but loaded with symlink
857 // the profiler could skip the dex due to location mismatch.
858 // To avoid this, we add the code paths to the temporary cache of 'to_be_resolved'
859 // locations. When the profiler thread executes we will resolve the paths to their
860 // real paths.
861 // Note that we delay taking the realpath to avoid spending more time than needed
862 // when registering location (as it is done during app launch).
863 AddTrackedLocationsToMap(output_filename,
864 code_paths,
865 &tracked_dex_base_locations_to_be_resolved_);
866 }
867
DumpInstanceInfo(std::ostream & os)868 void ProfileSaver::DumpInstanceInfo(std::ostream& os) {
869 MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
870 if (instance_ != nullptr) {
871 instance_->DumpInfo(os);
872 }
873 }
874
DumpInfo(std::ostream & os)875 void ProfileSaver::DumpInfo(std::ostream& os) {
876 os << "ProfileSaver total_bytes_written=" << total_bytes_written_ << '\n'
877 << "ProfileSaver total_number_of_writes=" << total_number_of_writes_ << '\n'
878 << "ProfileSaver total_number_of_code_cache_queries="
879 << total_number_of_code_cache_queries_ << '\n'
880 << "ProfileSaver total_number_of_skipped_writes=" << total_number_of_skipped_writes_ << '\n'
881 << "ProfileSaver total_number_of_failed_writes=" << total_number_of_failed_writes_ << '\n'
882 << "ProfileSaver total_ms_of_sleep=" << total_ms_of_sleep_ << '\n'
883 << "ProfileSaver total_ms_of_work=" << NsToMs(total_ns_of_work_) << '\n'
884 << "ProfileSaver max_number_profile_entries_cached="
885 << max_number_of_profile_entries_cached_ << '\n'
886 << "ProfileSaver total_number_of_hot_spikes=" << total_number_of_hot_spikes_ << '\n'
887 << "ProfileSaver total_number_of_wake_ups=" << total_number_of_wake_ups_ << '\n';
888 }
889
890
ForceProcessProfiles()891 void ProfileSaver::ForceProcessProfiles() {
892 ProfileSaver* saver = nullptr;
893 {
894 MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
895 saver = instance_;
896 }
897 // TODO(calin): this is not actually thread safe as the instance_ may have been deleted,
898 // but we only use this in testing when we now this won't happen.
899 // Refactor the way we handle the instance so that we don't end up in this situation.
900 if (saver != nullptr) {
901 saver->ProcessProfilingInfo(/*force_save=*/true, /*number_of_new_methods=*/nullptr);
902 }
903 }
904
HasSeenMethod(const std::string & profile,bool hot,MethodReference ref)905 bool ProfileSaver::HasSeenMethod(const std::string& profile, bool hot, MethodReference ref) {
906 MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
907 if (instance_ != nullptr) {
908 ProfileCompilationInfo info(Runtime::Current()->GetArenaPool());
909 if (!info.Load(profile, /*clear_if_invalid=*/false)) {
910 return false;
911 }
912 ProfileCompilationInfo::MethodHotness hotness = info.GetMethodHotness(ref);
913 // Ignore hot parameter for now since it was causing test 595 to be flaky. TODO: Investigate.
914 // b/63635729
915 UNUSED(hot);
916 return hotness.IsInProfile();
917 }
918 return false;
919 }
920
ResolveTrackedLocations()921 void ProfileSaver::ResolveTrackedLocations() {
922 SafeMap<std::string, std::set<std::string>> locations_to_be_resolved;
923 {
924 // Make a copy so that we don't hold the lock while doing I/O.
925 MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
926 locations_to_be_resolved = tracked_dex_base_locations_to_be_resolved_;
927 tracked_dex_base_locations_to_be_resolved_.clear();
928 }
929
930 // Resolve the locations.
931 SafeMap<std::string, std::vector<std::string>> resolved_locations_map;
932 for (const auto& it : locations_to_be_resolved) {
933 const std::string& filename = it.first;
934 const std::set<std::string>& locations = it.second;
935 auto resolved_locations_it = resolved_locations_map.Put(
936 filename,
937 std::vector<std::string>(locations.size()));
938
939 for (const auto& location : locations) {
940 UniqueCPtr<const char[]> location_real(realpath(location.c_str(), nullptr));
941 // Note that it's ok if we cannot get the real path.
942 if (location_real != nullptr) {
943 resolved_locations_it->second.emplace_back(location_real.get());
944 }
945 }
946 }
947
948 // Add the resolved locations to the tracked collection.
949 MutexLock mu(Thread::Current(), *Locks::profiler_lock_);
950 for (const auto& it : resolved_locations_map) {
951 AddTrackedLocationsToMap(it.first, it.second, &tracked_dex_base_locations_);
952 }
953 }
954
955 } // namespace art
956