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 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 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 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 106 ProfileSaver::~ProfileSaver() { 107 for (auto& it : profile_cache_) { 108 delete it.second; 109 } 110 } 111 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 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 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 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 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: 248 explicit ScopedDefaultPriority(pthread_t thread) : thread_(thread) { 249 SetProfileSaverThreadPriority(thread_, GetDefaultThreadPriority()); 250 } 251 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: 265 explicit GetClassLoadersVisitor(VariableSizedHandleScope* hs, 266 std::vector<Handle<mirror::ClassLoader>>* class_loaders) 267 : hs_(hs), 268 class_loaders_(class_loaders) {} 269 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: 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 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. 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 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 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 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 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 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 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 803 bool ProfileSaver::ShuttingDown(Thread* self) { 804 MutexLock mu(self, *Locks::profiler_lock_); 805 return shutting_down_; 806 } 807 808 bool ProfileSaver::IsStarted() { 809 MutexLock mu(Thread::Current(), *Locks::profiler_lock_); 810 return instance_ != nullptr; 811 } 812 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 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 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 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 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 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 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