1 /* 2 * Copyright (C) 2024 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 package android.os.profiling; 18 19 import android.annotation.NonNull; 20 import android.annotation.Nullable; 21 import android.content.Context; 22 import android.icu.text.SimpleDateFormat; 23 import android.icu.util.Calendar; 24 import android.icu.util.TimeZone; 25 import android.os.Binder; 26 import android.os.Bundle; 27 import android.os.Environment; 28 import android.os.FileUtils; 29 import android.os.Handler; 30 import android.os.HandlerThread; 31 import android.os.IBinder; 32 import android.os.IProfilingResultCallback; 33 import android.os.IProfilingService; 34 import android.os.ParcelFileDescriptor; 35 import android.os.ProfilingManager; 36 import android.os.ProfilingResult; 37 import android.os.ProfilingTrigger; 38 import android.os.ProfilingTriggerValueParcel; 39 import android.os.ProfilingTriggersWrapper; 40 import android.os.QueuedResultsWrapper; 41 import android.os.RemoteException; 42 import android.provider.DeviceConfig; 43 import android.text.TextUtils; 44 import android.util.ArrayMap; 45 import android.util.AtomicFile; 46 import android.util.Log; 47 import android.util.SparseArray; 48 49 import com.android.internal.annotations.GuardedBy; 50 import com.android.internal.annotations.VisibleForTesting; 51 import com.android.server.SystemService; 52 53 import java.io.File; 54 import java.io.FileInputStream; 55 import java.io.FileOutputStream; 56 import java.io.FilenameFilter; 57 import java.io.IOException; 58 import java.nio.file.Files; 59 import java.nio.file.Path; 60 import java.util.ArrayList; 61 import java.util.Arrays; 62 import java.util.List; 63 import java.util.Locale; 64 import java.util.Random; 65 import java.util.Set; 66 import java.util.UUID; 67 import java.util.concurrent.Executors; 68 import java.util.concurrent.ScheduledExecutorService; 69 import java.util.concurrent.ScheduledFuture; 70 import java.util.concurrent.TimeUnit; 71 import java.util.concurrent.atomic.AtomicInteger; 72 import java.util.function.Consumer; 73 74 public class ProfilingService extends IProfilingService.Stub { 75 private static final String TAG = ProfilingService.class.getSimpleName(); 76 private static final boolean DEBUG = false; 77 78 private static final String TEMP_TRACE_PATH = "/data/misc/perfetto-traces/profiling/"; 79 private static final String OUTPUT_FILE_RELATIVE_PATH = "/profiling/"; 80 private static final String OUTPUT_FILE_SECTION_SEPARATOR = "_"; 81 private static final String OUTPUT_FILE_PREFIX = "profile"; 82 // Keep in sync with {@link ProfilingFrameworkTests}. 83 private static final String OUTPUT_FILE_JAVA_HEAP_DUMP_SUFFIX = ".perfetto-java-heap-dump"; 84 private static final String OUTPUT_FILE_HEAP_PROFILE_SUFFIX = ".perfetto-heap-profile"; 85 private static final String OUTPUT_FILE_STACK_SAMPLING_SUFFIX = ".perfetto-stack-sample"; 86 private static final String OUTPUT_FILE_TRACE_SUFFIX = ".perfetto-trace"; 87 private static final String OUTPUT_FILE_UNREDACTED_TRACE_SUFFIX = ".perfetto-trace-unredacted"; 88 private static final String OUTPUT_FILE_TRIGGER = "trigger"; 89 private static final String OUTPUT_FILE_IN_PROGRESS = "in-progress"; 90 91 private static final String PERSIST_SYSTEM_DIR = "system"; 92 private static final String PERSIST_STORE_DIR = "profiling_service_data"; 93 private static final String QUEUED_RESULTS_INFO_FILE = "profiling_queued_results_info"; 94 private static final String APP_TRIGGERS_INFO_FILE = "profiling_app_triggers_info"; 95 96 // Used for unique session name only, not filename. 97 private static final String SYSTEM_TRIGGERED_SESSION_NAME_PREFIX = "system_triggered_session_"; 98 99 private static final int TAG_MAX_CHARS_FOR_FILENAME = 20; 100 101 private static final int PERFETTO_DESTROY_DEFAULT_TIMEOUT_MS = 10 * 1000; 102 103 private static final int DEFAULT_MAX_RESULT_REDELIVERY_COUNT = 3; 104 105 private static final int REDACTION_DEFAULT_MAX_RUNTIME_ALLOTTED_MS = 20 * 1000; 106 107 private static final int REDACTION_DEFAULT_CHECK_FREQUENCY_MS = 2 * 1000; 108 109 // The cadence at which the profiling process will be checked after the initial delay 110 // has elapsed. 111 private static final int PROFILING_DEFAULT_RECHECK_DELAY_MS = 5 * 1000; 112 113 private static final int CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_DEFAULT_MS = 24 * 60 * 60 * 1000; 114 private static final int CLEAR_TEMPORARY_DIRECTORY_BOOT_DELAY_DEFAULT_MS = 5 * 60 * 1000; 115 116 // The longest amount of time that we will retain a queued result and continue retrying to 117 // deliver it. After this amount of time the result will be discarded. 118 @VisibleForTesting 119 public static final int QUEUED_RESULT_MAX_RETAINED_DURATION_MS = 7 * 24 * 60 * 60 * 1000; 120 121 private static final int PERSIST_TO_DISK_DEFAULT_FREQUENCY_MS = 30 * 60 * 1000; 122 123 // Targeting a period of around 24 hours, so set max and min to 24 +/- 6 hours, respectively. 124 private static final int DEFAULT_SYSTEM_TRIGGERED_TRACE_MIN_PERIOD_SECONDS = 18 * 60 * 60; 125 private static final int DEFAULT_SYSTEM_TRIGGERED_TRACE_MAX_PERIOD_SECONDS = 30 * 60 * 60; 126 127 private final Context mContext; 128 private final Object mLock = new Object(); 129 private final HandlerThread mHandlerThread = new HandlerThread("ProfilingService"); 130 131 @VisibleForTesting public RateLimiter mRateLimiter = null; 132 133 // Timeout for Perfetto process to successfully stop after we try to stop it. 134 private int mPerfettoDestroyTimeoutMs; 135 private int mMaxResultRedeliveryCount; 136 private int mProfilingRecheckDelayMs; 137 138 @GuardedBy("mLock") 139 private long mLastClearTemporaryDirectoryTimeMs = 0; 140 private int mClearTemporaryDirectoryFrequencyMs; 141 private final int mClearTemporaryDirectoryBootDelayMs; 142 143 private int mRedactionCheckFrequencyMs; 144 private int mRedactionMaxRuntimeAllottedMs; 145 146 private Handler mHandler; 147 148 private Calendar mCalendar = null; 149 private SimpleDateFormat mDateFormat = null; 150 151 // uid indexed collection of lists of callbacks for results. 152 @VisibleForTesting 153 public SparseArray<List<IProfilingResultCallback>> mResultCallbacks = new SparseArray<>(); 154 155 // Request UUID key indexed storage of active tracing sessions. Currently only 1 active session 156 // is supported at a time, but this will be used in future to support multiple. 157 @VisibleForTesting 158 public ArrayMap<String, TracingSession> mActiveTracingSessions = new ArrayMap<>(); 159 160 // System triggered trace is another actively running profiling session, but not included in 161 // the active sessions above as it's not associated with a TracingSession until it has been 162 // cloned. 163 @VisibleForTesting 164 @GuardedBy("mLock") 165 public Process mSystemTriggeredTraceProcess = null; 166 @VisibleForTesting 167 public String mSystemTriggeredTraceUniqueSessionName = null; 168 private long mLastStartedSystemTriggeredTraceMs = 0; 169 170 // Map of uid + package name to a sparse array of trigger objects. 171 @VisibleForTesting 172 public ProcessMap<SparseArray<ProfilingTriggerData>> mAppTriggers = new ProcessMap<>(); 173 @VisibleForTesting 174 public boolean mAppTriggersLoaded = false; 175 176 // uid indexed storage of completed tracing sessions that have not yet successfully handled the 177 // result. 178 @VisibleForTesting 179 public SparseArray<List<TracingSession>> mQueuedTracingResults = new SparseArray<>(); 180 181 private boolean mPersistScheduled = false; 182 // Frequency of 0 would result in immediate persist. 183 @GuardedBy("mLock") 184 private AtomicInteger mPersistFrequencyMs; 185 @GuardedBy("mLock") 186 private long mLastPersistedTimestampMs = 0L; 187 private Runnable mPersistRunnable = null; 188 189 /** The path to the directory which includes all persisted results from this class. */ 190 @VisibleForTesting 191 public File mPersistStoreDir = null; 192 193 /** The queued results data file, persisted in the storage. */ 194 @VisibleForTesting 195 public File mPersistQueueFile = null; 196 197 /** The app triggers results data file, persisted in the storage. */ 198 @VisibleForTesting 199 public File mPersistAppTriggersFile = null; 200 201 /** To be disabled for testing only. */ 202 @GuardedBy("mLock") 203 private boolean mKeepResultInTempDir = false; 204 205 /** Executor for scheduling system triggered profiling trace. */ 206 private ScheduledExecutorService mScheduledExecutorService = null; 207 208 /** Future for the start system triggered trace. */ 209 @VisibleForTesting 210 public ScheduledFuture<?> mStartSystemTriggeredTraceScheduledFuture = null; 211 212 @GuardedBy("mLock") 213 private AtomicInteger mSystemTriggeredTraceMinPeriodSeconds; 214 @GuardedBy("mLock") 215 private AtomicInteger mSystemTriggeredTraceMaxPeriodSeconds; 216 217 /** 218 * Package name of app being tested, or null if no app is being tested. To be used both for 219 * automated testing and developer manual testing. 220 * 221 * Setting this package name will: 222 * - Ensure a system triggered trace is always running. 223 * - Allow all triggers for the specified package name to be executed. 224 * 225 * This is not intended to be set directly. Instead, set this package name by using 226 * device_config commands described at {@link ProfilingManager}. 227 * 228 * There is no time limit on how long this can be left enabled for. 229 */ 230 private String mTestPackageName = null; 231 232 /** 233 * State the {@link TracingSession} is in. 234 * 235 * State represents the most recently confirmed completed step in the process. Steps represent 236 * save points which the process would have to go back to if it did not successfully reach the 237 * next step. 238 * 239 * States are sequential. It can be expected that state value will only increase throughout a 240 * sessions life. 241 * 242 * At different states, the containing object can be assumed to exist in different data 243 * structures as follows: 244 * REQUESTED - Local only, not in any data structure. 245 * APPROVED - Local only, not in any data structure. 246 * PROFILING_STARTED - Stored in {@link mActiveTracingSessions}. 247 * PROFILING_FINISHED - Stored in {@link mQueuedTracingResults}. 248 * REDACTED - Stored in {@link mQueuedTracingResults}. 249 * COPIED_FILE - Stored in {@link mQueuedTracingResults}. 250 * ERROR_OCCURRED - Stored in {@link mQueuedTracingResults}. 251 * NOTIFIED_REQUESTER - Stored in {@link mQueuedTracingResults}. 252 * CLEANED_UP - Local only, not in any data structure. 253 */ 254 public enum TracingState { 255 // Intentionally skipping 0 since proto, which will be used for persist, treats it as unset. 256 REQUESTED(1), 257 APPROVED(2), 258 PROFILING_STARTED(3), 259 PROFILING_FINISHED(4), 260 REDACTED(5), 261 COPIED_FILE(6), 262 ERROR_OCCURRED(7), 263 NOTIFIED_REQUESTER(8), 264 CLEANED_UP(9); 265 266 /** Data structure for efficiently mapping int values back to their enum values. */ 267 private static List<TracingState> sStatesList; 268 269 static { 270 sStatesList = Arrays.asList(TracingState.values()); 271 } 272 273 private final int mValue; TracingState(int value)274 TracingState(int value) { 275 mValue = value; 276 } 277 278 /** Obtain TracingState from int value. */ of(int value)279 public static TracingState of(int value) { 280 if (value < 1 || value >= sStatesList.size() + 1) { 281 return null; 282 } 283 284 return sStatesList.get(value - 1); 285 } 286 getValue()287 public int getValue() { 288 return mValue; 289 } 290 } 291 292 @VisibleForTesting ProfilingService(Context context)293 public ProfilingService(Context context) { 294 mContext = context; 295 296 mPerfettoDestroyTimeoutMs = DeviceConfigHelper.getInt( 297 DeviceConfigHelper.PERFETTO_DESTROY_TIMEOUT_MS, 298 PERFETTO_DESTROY_DEFAULT_TIMEOUT_MS); 299 300 mMaxResultRedeliveryCount = DeviceConfigHelper.getInt( 301 DeviceConfigHelper.MAX_RESULT_REDELIVERY_COUNT, 302 DEFAULT_MAX_RESULT_REDELIVERY_COUNT); 303 304 mProfilingRecheckDelayMs = DeviceConfigHelper.getInt( 305 DeviceConfigHelper.PROFILING_RECHECK_DELAY_MS, 306 PROFILING_DEFAULT_RECHECK_DELAY_MS); 307 308 mClearTemporaryDirectoryFrequencyMs = DeviceConfigHelper.getInt( 309 DeviceConfigHelper.CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_MS, 310 CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_DEFAULT_MS); 311 312 mClearTemporaryDirectoryBootDelayMs = DeviceConfigHelper.getInt( 313 DeviceConfigHelper.CLEAR_TEMPORARY_DIRECTORY_BOOT_DELAY_MS, 314 CLEAR_TEMPORARY_DIRECTORY_BOOT_DELAY_DEFAULT_MS); 315 316 mRedactionCheckFrequencyMs = DeviceConfigHelper.getInt( 317 DeviceConfigHelper.REDACTION_CHECK_FREQUENCY_MS, 318 REDACTION_DEFAULT_CHECK_FREQUENCY_MS); 319 320 mRedactionMaxRuntimeAllottedMs = DeviceConfigHelper.getInt( 321 DeviceConfigHelper.REDACTION_MAX_RUNTIME_ALLOTTED_MS, 322 REDACTION_DEFAULT_MAX_RUNTIME_ALLOTTED_MS); 323 324 mHandlerThread.start(); 325 326 // Get initial value for whether unredacted trace should be retained. 327 // This is used for (automated and manual) testing only. 328 synchronized (mLock) { 329 mKeepResultInTempDir = DeviceConfigHelper.getTestBoolean( 330 DeviceConfigHelper.DISABLE_DELETE_TEMPORARY_RESULTS, false); 331 332 mPersistFrequencyMs = new AtomicInteger(DeviceConfigHelper.getInt( 333 DeviceConfigHelper.PERSIST_TO_DISK_FREQUENCY_MS, 334 PERSIST_TO_DISK_DEFAULT_FREQUENCY_MS)); 335 336 mSystemTriggeredTraceMinPeriodSeconds = new AtomicInteger(DeviceConfigHelper.getInt( 337 DeviceConfigHelper.SYSTEM_TRIGGERED_TRACE_MIN_PERIOD_SECONDS, 338 DEFAULT_SYSTEM_TRIGGERED_TRACE_MIN_PERIOD_SECONDS)); 339 340 mSystemTriggeredTraceMaxPeriodSeconds = new AtomicInteger(DeviceConfigHelper.getInt( 341 DeviceConfigHelper.SYSTEM_TRIGGERED_TRACE_MAX_PERIOD_SECONDS, 342 DEFAULT_SYSTEM_TRIGGERED_TRACE_MAX_PERIOD_SECONDS)); 343 } 344 // Now subscribe to updates on test config. 345 DeviceConfig.addOnPropertiesChangedListener(DeviceConfigHelper.NAMESPACE_TESTING, 346 mContext.getMainExecutor(), new DeviceConfig.OnPropertiesChangedListener() { 347 @Override 348 public void onPropertiesChanged(@NonNull DeviceConfig.Properties properties) { 349 synchronized (mLock) { 350 mKeepResultInTempDir = properties.getBoolean( 351 DeviceConfigHelper.DISABLE_DELETE_TEMPORARY_RESULTS, false); 352 getRateLimiter().maybeUpdateRateLimiterDisabled(properties); 353 354 String newTestPackageName = properties.getString( 355 DeviceConfigHelper.SYSTEM_TRIGGERED_TEST_PACKAGE_NAME, null); 356 handleTestPackageChangeLocked(newTestPackageName); 357 } 358 } 359 }); 360 361 // Subscribe to updates on the main config. 362 DeviceConfig.addOnPropertiesChangedListener(DeviceConfigHelper.NAMESPACE, 363 mContext.getMainExecutor(), new DeviceConfig.OnPropertiesChangedListener() { 364 @Override 365 public void onPropertiesChanged(@NonNull DeviceConfig.Properties properties) { 366 synchronized (mLock) { 367 getRateLimiter().maybeUpdateConfigs(properties); 368 Configs.maybeUpdateConfigs(properties); 369 370 mPerfettoDestroyTimeoutMs = properties.getInt( 371 DeviceConfigHelper.PERFETTO_DESTROY_TIMEOUT_MS, 372 mPerfettoDestroyTimeoutMs); 373 374 mMaxResultRedeliveryCount = properties.getInt( 375 DeviceConfigHelper.MAX_RESULT_REDELIVERY_COUNT, 376 mMaxResultRedeliveryCount); 377 378 mProfilingRecheckDelayMs = properties.getInt( 379 DeviceConfigHelper.PROFILING_RECHECK_DELAY_MS, 380 mProfilingRecheckDelayMs); 381 382 mClearTemporaryDirectoryFrequencyMs = properties.getInt( 383 DeviceConfigHelper.CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_MS, 384 mClearTemporaryDirectoryFrequencyMs); 385 386 // No need to handle updates for 387 // {@link mClearTemporaryDirectoryBootDelayMs} as it's only used on 388 // initialization of this class so by the time this occurs it will never 389 // be used again. 390 391 mRedactionCheckFrequencyMs = properties.getInt( 392 DeviceConfigHelper.REDACTION_CHECK_FREQUENCY_MS, 393 mRedactionCheckFrequencyMs); 394 395 mRedactionMaxRuntimeAllottedMs = properties.getInt( 396 DeviceConfigHelper.REDACTION_MAX_RUNTIME_ALLOTTED_MS, 397 mRedactionMaxRuntimeAllottedMs); 398 399 mPersistFrequencyMs.set(properties.getInt( 400 DeviceConfigHelper.PERSIST_TO_DISK_FREQUENCY_MS, 401 mPersistFrequencyMs.get())); 402 403 mSystemTriggeredTraceMinPeriodSeconds.set(DeviceConfigHelper.getInt( 404 DeviceConfigHelper.SYSTEM_TRIGGERED_TRACE_MIN_PERIOD_SECONDS, 405 mSystemTriggeredTraceMinPeriodSeconds.get())); 406 407 mSystemTriggeredTraceMaxPeriodSeconds.set(DeviceConfigHelper.getInt( 408 DeviceConfigHelper.SYSTEM_TRIGGERED_TRACE_MAX_PERIOD_SECONDS, 409 mSystemTriggeredTraceMaxPeriodSeconds.get())); 410 } 411 } 412 }); 413 414 // Schedule initial storage cleanup and system triggered trace start after a delay so as not 415 // to increase non-critical or work during boot. 416 getHandler().postDelayed(new Runnable() { 417 @Override 418 public void run() { 419 scheduleNextSystemTriggeredTraceStart(); 420 maybeCleanupTemporaryDirectory(); 421 } 422 }, mClearTemporaryDirectoryBootDelayMs); 423 424 // Load the queue and triggers right away. 425 loadQueueFromPersistedData(); 426 loadAppTriggersFromPersistedData(); 427 } 428 429 /** 430 * Load persisted queue entries. If any issue is encountered reading/parsing the file, delete it 431 * and return as failure to load queue does not block the feature. 432 */ 433 @VisibleForTesting loadQueueFromPersistedData()434 public void loadQueueFromPersistedData() { 435 if (!Flags.persistQueue()) { 436 return; 437 } 438 439 // Setup persist files 440 try { 441 if (!setupPersistQueueFiles()) { 442 // If setting up the directory and file was unsuccessful then just return. Past and 443 // future queued results will be lost, but the feature as a whole still works. 444 if (DEBUG) Log.d(TAG, "Failed to setup queue persistence directory/files."); 445 return; 446 } 447 } catch (SecurityException e) { 448 // Can't access files. 449 if (DEBUG) Log.e(TAG, "Failed to setup queue persistence directory/files.", e); 450 return; 451 } 452 453 // Check if file exists 454 try { 455 if (!mPersistQueueFile.exists()) { 456 // No file, nothing to load. This is an expected state for before the feature has 457 // ever been used or if the queue was emptied. 458 if (DEBUG) { 459 Log.d(TAG, "Queue persistence file does not exist, skipping load from disk."); 460 } 461 return; 462 } 463 } catch (SecurityException e) { 464 // Can't access file. 465 if (DEBUG) Log.e(TAG, "Exception accessing queue persistence file", e); 466 return; 467 } 468 469 // Read the file 470 AtomicFile persistFile = new AtomicFile(mPersistQueueFile); 471 byte[] bytes; 472 try { 473 bytes = persistFile.readFully(); 474 } catch (IOException e) { 475 if (DEBUG) Log.e(TAG, "Exception reading queue persistence file", e); 476 // Failed to read the file. No reason to believe we'll have better luck next time, 477 // delete the file and return. Results in the queue will be lost. 478 deletePersistQueueFile(); 479 return; 480 } 481 if (bytes.length == 0) { 482 if (DEBUG) Log.d(TAG, "Queue persistence file is empty, skipping load from disk."); 483 // Empty queue persist file. Delete the file and return. 484 deletePersistQueueFile(); 485 return; 486 } 487 488 // Parse file bytes to proto 489 QueuedResultsWrapper wrapper; 490 try { 491 wrapper = QueuedResultsWrapper.parseFrom(bytes); 492 } catch (Exception e) { 493 if (DEBUG) Log.e(TAG, "Error parsing proto from persisted bytes", e); 494 // Failed to parse the file contents. No reason to believe we'll have better luck next 495 // time, delete the file and return. Results in the queue will be lost. 496 deletePersistQueueFile(); 497 return; 498 } 499 500 // Populate in memory records store 501 for (int i = 0; i < wrapper.getSessionsCount(); i++) { 502 QueuedResultsWrapper.TracingSession sessionsProto = wrapper.getSessions(i); 503 TracingSession session = new TracingSession(sessionsProto); 504 // Since we're populating the in memory store from the persisted queue we don't want to 505 // trigger a persist, so pass param false. If we did trigger the persist from here, it 506 // would overwrite the file with the first record only and then queue the remaining 507 // records for later, thereby leaving the persisted queue with less data than it 508 // currently contains and potentially leading to lost data in event of shutdown before 509 // the scheduled persist occurs. 510 moveSessionToQueue(session, false); 511 } 512 } 513 514 /** 515 * Load persisted app triggers from disk. 516 * 517 * If any issue is encountered during loading, mark as completed and delete the file. Persisted 518 * app triggers will be lost. 519 */ 520 @VisibleForTesting loadAppTriggersFromPersistedData()521 public void loadAppTriggersFromPersistedData() { 522 // Setup persist files 523 try { 524 if (!setupPersistAppTriggerFiles()) { 525 // If setting up the directory and file was unsuccessful then just return without 526 // marking loaded so it can be tried again. 527 if (DEBUG) Log.d(TAG, "Failed to setup app trigger persistence directory/files."); 528 return; 529 } 530 } catch (SecurityException e) { 531 // Can't access files. 532 Log.w(TAG, "Failed to setup app trigger persistence directory/files.", e); 533 return; 534 } 535 536 // Check if file exists 537 try { 538 if (!mPersistAppTriggersFile.exists()) { 539 // No file, nothing to load. This is an expected state for before the feature has 540 // ever been used or if the triggers were empty. 541 if (DEBUG) { 542 Log.d(TAG, "App trigger persistence file does not exist, skipping load from " 543 + "disk."); 544 } 545 mAppTriggersLoaded = true; 546 return; 547 } 548 } catch (SecurityException e) { 549 // Can't access file. 550 if (DEBUG) Log.e(TAG, "Exception accessing app triggers persistence file", e); 551 return; 552 } 553 554 // Read the file 555 AtomicFile persistFile = new AtomicFile(mPersistAppTriggersFile); 556 byte[] bytes; 557 try { 558 bytes = persistFile.readFully(); 559 } catch (IOException e) { 560 Log.w(TAG, "Exception reading app triggers persistence file", e); 561 // Failed to read the file. No reason to believe we'll have better luck next time, 562 // delete the file and return. Persisted triggers will be lost until the app re-adds 563 // them. 564 deletePersistAppTriggersFile(); 565 mAppTriggersLoaded = true; 566 return; 567 } 568 if (bytes.length == 0) { 569 if (DEBUG) Log.d(TAG, "App triggers persistence file empty, skipping load from disk."); 570 // Empty app triggers persist file. Delete the file, mark loaded, and return. 571 deletePersistAppTriggersFile(); 572 mAppTriggersLoaded = true; 573 return; 574 } 575 576 // Parse file bytes to proto 577 ProfilingTriggersWrapper wrapper; 578 try { 579 wrapper = ProfilingTriggersWrapper.parseFrom(bytes); 580 } catch (Exception e) { 581 Log.w(TAG, "Error parsing proto from persisted bytes", e); 582 // Failed to parse the file contents. No reason to believe we'll have better luck next 583 // time, delete the file, mark loaded, and return. Persisted app triggers will be lost 584 // until re-added by the app. 585 deletePersistAppTriggersFile(); 586 mAppTriggersLoaded = true; 587 return; 588 } 589 590 // Populate in memory app triggers store 591 for (int i = 0; i < wrapper.getTriggersCount(); i++) { 592 ProfilingTriggersWrapper.ProfilingTrigger triggerProto = wrapper.getTriggers(i); 593 addTrigger(new ProfilingTriggerData(triggerProto), false); 594 } 595 596 mAppTriggersLoaded = true; 597 } 598 599 /** Setup the directory and file for persisting queue. */ 600 @VisibleForTesting setupPersistQueueFiles()601 public boolean setupPersistQueueFiles() { 602 if (mPersistStoreDir == null) { 603 if (!setupPersistDir()) { 604 return false; 605 } 606 } 607 mPersistQueueFile = new File(mPersistStoreDir, QUEUED_RESULTS_INFO_FILE); 608 return true; 609 } 610 611 /** Setup the directory and file for persisting app triggers. */ 612 @VisibleForTesting setupPersistAppTriggerFiles()613 public boolean setupPersistAppTriggerFiles() { 614 if (mPersistStoreDir == null) { 615 if (!setupPersistDir()) { 616 return false; 617 } 618 } 619 mPersistAppTriggersFile = new File(mPersistStoreDir, APP_TRIGGERS_INFO_FILE); 620 return true; 621 } 622 623 /** Setup the directory and file for persisting. */ 624 @VisibleForTesting setupPersistDir()625 public boolean setupPersistDir() { 626 File dataDir = Environment.getDataDirectory(); 627 File systemDir = new File(dataDir, PERSIST_SYSTEM_DIR); 628 mPersistStoreDir = new File(systemDir, PERSIST_STORE_DIR); 629 return createDir(mPersistStoreDir); 630 } 631 632 /** Delete the persist queue file. */ 633 @VisibleForTesting deletePersistQueueFile()634 public void deletePersistQueueFile() { 635 try { 636 mPersistQueueFile.delete(); 637 if (DEBUG) Log.d(TAG, "Deleted queue persist file."); 638 } catch (SecurityException e) { 639 // Can't delete file. 640 if (DEBUG) Log.d(TAG, "Failed to delete queue persist file", e); 641 } 642 } 643 644 /** Delete the persist app triggers file. */ 645 @VisibleForTesting deletePersistAppTriggersFile()646 public void deletePersistAppTriggersFile() { 647 try { 648 mPersistAppTriggersFile.delete(); 649 if (DEBUG) Log.d(TAG, "Deleted app triggers persist file."); 650 } catch (SecurityException e) { 651 // Can't delete file. 652 if (DEBUG) Log.d(TAG, "Failed to delete app triggers persist file", e); 653 } 654 } 655 createDir(File dir)656 private static boolean createDir(File dir) throws SecurityException { 657 if (dir.mkdir()) { 658 return true; 659 } 660 661 if (dir.exists()) { 662 return dir.isDirectory(); 663 } 664 665 return false; 666 } 667 668 /** 669 * Schedule the next start of system triggered profiling trace for a random time between min and 670 * max period. 671 */ 672 @VisibleForTesting scheduleNextSystemTriggeredTraceStart()673 public void scheduleNextSystemTriggeredTraceStart() { 674 if (!Flags.systemTriggeredProfilingNew()) { 675 // Feature disabled. 676 return; 677 } 678 679 if (mStartSystemTriggeredTraceScheduledFuture != null) { 680 // If an existing start is already scheduled, don't schedule another. 681 // This should not happen. 682 Log.e(TAG, "Attempted to schedule a system triggered trace start with one already " 683 + "scheduled."); 684 return; 685 } 686 687 if (mScheduledExecutorService == null) { 688 mScheduledExecutorService = Executors.newSingleThreadScheduledExecutor(); 689 } 690 691 int scheduledDelaySeconds; 692 693 synchronized (mLock) { 694 // It's important that trace doesn't always run at the same time as this will bias the 695 // results, so grab a random number between min and max. 696 scheduledDelaySeconds = mSystemTriggeredTraceMinPeriodSeconds.get() 697 + (new Random()).nextInt(mSystemTriggeredTraceMaxPeriodSeconds.get() 698 - mSystemTriggeredTraceMinPeriodSeconds.get()); 699 700 if (DEBUG) { 701 Log.d(TAG, String.format("System triggered trace scheduled in %d seconds for params" 702 + " min %d and max %d seconds.", 703 scheduledDelaySeconds, 704 mSystemTriggeredTraceMinPeriodSeconds.get(), 705 mSystemTriggeredTraceMaxPeriodSeconds.get())); 706 } 707 } 708 709 // Scheduling of system triggered trace setup is done out of the lock to avoid a potential 710 // deadlock in the case of really frequent triggering due to low min/max values for period. 711 mStartSystemTriggeredTraceScheduledFuture = mScheduledExecutorService.schedule(() -> { 712 // Start the system triggered trace. 713 startSystemTriggeredTrace(); 714 715 mStartSystemTriggeredTraceScheduledFuture = null; 716 717 // In all cases, schedule again. Feature flagged off is handled earlier in this 718 // method, and all return cases in {@link #startSystemTriggeredTrace} should result 719 // in trying again at the next regularly scheduled time. 720 scheduleNextSystemTriggeredTraceStart(); 721 }, scheduledDelaySeconds, TimeUnit.SECONDS); 722 } 723 724 /** 725 * This is the core method that keeps the profiling flow moving. 726 * 727 * This is the only way that state should be set. Do not use {@link TracingSession#setState} 728 * directly. 729 * 730 * The passed newState represents the state that was just completed. Passing null for new state 731 * will continue using the current state as the last completed state, this is intended only for 732 * resuming the queue. 733 * 734 * Generally, this should be the last call in a method before returning. 735 */ 736 @VisibleForTesting advanceTracingSession(TracingSession session, @Nullable TracingState newState)737 public void advanceTracingSession(TracingSession session, @Nullable TracingState newState) { 738 if (newState == null) { 739 if (session.getRetryCount() == 0) { 740 // The new state should only be null if this is triggered from the queue in which 741 // case the retry count should be greater than 0. If retry count is 0 here then 742 // we're in an unexpected state. Cleanup and discard. Result will be lost. 743 cleanupTracingSession(session); 744 return; 745 } 746 } else if (newState == session.getState()) { 747 // This should never happen. 748 // If the state is not actually changing then we may find ourselves in an infinite 749 // loop. Terminate this attempt and increment the retry count to ensure there's a 750 // path to breaking out of a potential infinite queue retries. 751 session.incrementRetryCount(); 752 return; 753 } else if (newState.getValue() < session.getState().getValue()) { 754 // This should also never happen. 755 // States should always move forward. If the state is trying to move backwards then 756 // we don't actually know what to do next. Clean up the session and delete 757 // everything. Results will be lost. 758 cleanupTracingSession(session); 759 return; 760 } else { 761 // The new state is not null so update the sessions state. 762 session.setState(newState); 763 } 764 765 switch (session.getState()) { 766 case REQUESTED: 767 // This should never happen as requested state is expected to handled by the request 768 // method, the first actionable state is approved. Ignore it. 769 if (DEBUG) { 770 Log.e(TAG, "Session attempting to advance with REQUESTED state unsupported."); 771 } 772 break; 773 case APPROVED: 774 // Session has been approved by rate limiter, so continue on to start profiling. 775 startProfiling(session); 776 break; 777 case PROFILING_STARTED: 778 // Profiling has been successfully started. Next step depends on whether or not the 779 // profiling is alive. 780 if (session.getActiveTrace() == null || !session.getActiveTrace().isAlive() 781 || session.getProcessResultRunnable() == null) { 782 // This really should not happen, but if profiling is not in correct started 783 // state then try to stop and continue processing it. 784 stopProfiling(session); 785 } // else: do nothing. The runnable we just verified exists will return us to this 786 // method when profiling is finished. 787 break; 788 case PROFILING_FINISHED: 789 // Next step depends on whether or not the result requires redaction. 790 if (needsRedaction(session)) { 791 // Redaction needed, kick it off. 792 handleRedactionRequiredResult(session); 793 } else { 794 // For results that don't require redaction, maybe log the location of the 795 // retained result after profiling completes. 796 handleRetainedTempFiles(session); 797 798 // No redaction needed, move straight to copying to app storage. 799 beginMoveFileToAppStorage(session); 800 } 801 break; 802 case REDACTED: 803 // For results that require redaction, maybe log the location of the retained result 804 // after redaction completes. 805 handleRetainedTempFiles(session); 806 807 // Redaction completed, move on to copying to app storage. 808 beginMoveFileToAppStorage(session); 809 break; 810 case COPIED_FILE: 811 // File has already been copied to app storage, proceed to callback. 812 session.setError(ProfilingResult.ERROR_NONE); 813 processTracingSessionResultCallback(session, true /* Continue advancing session */); 814 815 // This is a good place to persist the queue if possible because the processing work 816 // is complete and we tried to send a callback to the app. If the callback 817 // succeeded, then we will already have recursed on this method with new state of 818 // NOTIFIED_REQUESTER and the only potential remaining work to be repeated will be 819 // cleanup. If the callback failed, then we won't have recursed here and we'll pick 820 // back up this stage next time thereby minimizing repeated work. 821 maybePersistToDisk(); 822 break; 823 case ERROR_OCCURRED: 824 // An error has occurred, proceed to callback. 825 processTracingSessionResultCallback(session, true /* Continue advancing session */); 826 827 // This is a good place to persist the queue if possible because the processing work 828 // is complete and we tried to send a callback to the app. If the callback 829 // succeeded, then we will already have recursed on this method with new state of 830 // NOTIFIED_REQUESTER and the only potential remaining work to be repeated will be 831 // cleanup. If the callback failed, then we won't have recursed here and we'll pick 832 // back up this stage next time thereby minimizing repeated work. 833 maybePersistToDisk(); 834 break; 835 case NOTIFIED_REQUESTER: 836 // Callback has been completed successfully, start cleanup. 837 cleanupTracingSession(session); 838 break; 839 case CLEANED_UP: 840 // Session was cleaned up, nothing left to do. 841 break; 842 } 843 } 844 845 /** Perform a temporary directory cleanup if it has been long enough to warrant one. */ maybeCleanupTemporaryDirectory()846 private void maybeCleanupTemporaryDirectory() { 847 synchronized (mLock) { 848 if (mLastClearTemporaryDirectoryTimeMs + mClearTemporaryDirectoryFrequencyMs 849 < System.currentTimeMillis()) { 850 cleanupTemporaryDirectoryLocked(TEMP_TRACE_PATH); 851 } 852 } 853 } 854 855 856 /** Cleanup untracked data stored in provided directory. */ 857 @GuardedBy("mLock") 858 @VisibleForTesting cleanupTemporaryDirectoryLocked(String temporaryDirectoryPath)859 public void cleanupTemporaryDirectoryLocked(String temporaryDirectoryPath) { 860 if (mKeepResultInTempDir) { 861 // Don't clean up any temporary files while {@link mKeepResultInTempDir} is enabled as 862 // files are being retained for testing purposes. 863 return; 864 } 865 866 // Obtain a list of all currently tracked files and create a filter with it. Filter is set 867 // to null if the list is empty as that will efficiently accept all files. 868 final List<String> trackedFilenames = getTrackedFilenames(); 869 FilenameFilter filenameFilter = trackedFilenames.isEmpty() ? null : new FilenameFilter() { 870 @Override 871 public boolean accept(File dir, String name) { 872 // We only want to accept files which are not in the tracked files list. 873 return !trackedFilenames.contains(name); 874 } 875 }; 876 877 // Now obtain a list of files in the provided directory that are not tracked. 878 File directory = new File(temporaryDirectoryPath); 879 File[] files = null; 880 try { 881 files = directory.listFiles(filenameFilter); 882 } catch (SecurityException e) { 883 // Couldn't get a list of files, can't cleanup anything. 884 if (DEBUG) { 885 Log.d(TAG, "Failed to get file list from temporary directory. Cleanup aborted.", e); 886 } 887 return; 888 } 889 890 if (files == null) { 891 // The path doesn't exist or an I/O error occurred. 892 if (DEBUG) { 893 Log.d(TAG, "Temporary directory doesn't exist or i/o error occurred. " 894 + "Cleanup aborted."); 895 } 896 return; 897 } 898 899 // Set time here as we'll either return due to no files or attempt to delete files, after 900 // either of which we should wait before checking again. 901 mLastClearTemporaryDirectoryTimeMs = System.currentTimeMillis(); 902 903 if (files.length == 0) { 904 // No files, nothing to cleanup. 905 if (DEBUG) Log.d(TAG, "No files in temporary directory to cleanup."); 906 return; 907 } 908 909 // Iterate through and delete them. 910 for (int i = 0; i < files.length; i++) { 911 try { 912 files[i].delete(); 913 } catch (SecurityException e) { 914 // Exception deleting file, keep trying for the others. 915 if (DEBUG) Log.d(TAG, "Exception deleting file from temp directory.", e); 916 } 917 } 918 } 919 920 /** 921 * Return a list of all filenames that are currently tracked in either the in progress 922 * collections or the queued results, including both redacted and unredacted. 923 */ getTrackedFilenames()924 private List<String> getTrackedFilenames() { 925 List<String> filenames = new ArrayList<String>(); 926 927 // If active sessions is not empty, iterate through and add the filenames from each. 928 if (!mActiveTracingSessions.isEmpty()) { 929 for (int i = 0; i < mActiveTracingSessions.size(); i++) { 930 TracingSession session = mActiveTracingSessions.valueAt(i); 931 String filename = session.getFileName(); 932 if (filename != null) { 933 filenames.add(filename); 934 } 935 String redactedFilename = session.getRedactedFileName(); 936 if (redactedFilename != null) { 937 filenames.add(redactedFilename); 938 } 939 } 940 } 941 942 // If queued sessions is not empty, iterate through and add the filenames from each. 943 if (mQueuedTracingResults.size() != 0) { 944 for (int i = 0; i < mQueuedTracingResults.size(); i++) { 945 List<TracingSession> perUidSessions = mQueuedTracingResults.valueAt(i); 946 if (!perUidSessions.isEmpty()) { 947 for (int j = 0; j < perUidSessions.size(); j++) { 948 TracingSession session = perUidSessions.get(j); 949 String filename = session.getFileName(); 950 if (filename != null) { 951 filenames.add(filename); 952 } 953 String redactedFilename = session.getRedactedFileName(); 954 if (redactedFilename != null) { 955 filenames.add(redactedFilename); 956 } 957 } 958 } 959 } 960 } 961 962 return filenames; 963 } 964 965 /** 966 * This method validates the request, arguments, whether the app is allowed to profile now, 967 * and if so, starts the profiling. 968 */ requestProfiling(int profilingType, Bundle params, String tag, long keyMostSigBits, long keyLeastSigBits, String packageName)969 public void requestProfiling(int profilingType, Bundle params, String tag, 970 long keyMostSigBits, long keyLeastSigBits, String packageName) { 971 int uid = Binder.getCallingUid(); 972 973 if (profilingType != ProfilingManager.PROFILING_TYPE_JAVA_HEAP_DUMP 974 && profilingType != ProfilingManager.PROFILING_TYPE_HEAP_PROFILE 975 && profilingType != ProfilingManager.PROFILING_TYPE_STACK_SAMPLING 976 && profilingType != ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) { 977 if (DEBUG) Log.d(TAG, "Invalid request profiling type: " + profilingType); 978 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 979 ProfilingResult.ERROR_FAILED_INVALID_REQUEST, null, tag, 980 "Invalid request profiling type", getTriggerTypeNone()); 981 return; 982 } 983 984 cleanupActiveTracingSessions(); 985 986 // Check if we're running another trace so we don't run multiple at once. 987 try { 988 if (areAnyTracesRunning()) { 989 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 990 ProfilingResult.ERROR_FAILED_PROFILING_IN_PROGRESS, null, tag, null, 991 getTriggerTypeNone()); 992 return; 993 } 994 } catch (RuntimeException e) { 995 if (DEBUG) Log.d(TAG, "Error communicating with perfetto", e); 996 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 997 ProfilingResult.ERROR_UNKNOWN, null, tag, "Error communicating with perfetto", 998 getTriggerTypeNone()); 999 return; 1000 } 1001 1002 if (packageName == null) { 1003 // This shouldn't happen as it should be checked on the app side. 1004 if (DEBUG) Log.d(TAG, "PackageName is null"); 1005 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 1006 ProfilingResult.ERROR_UNKNOWN, null, tag, "Couldn't determine package name", 1007 getTriggerTypeNone()); 1008 return; 1009 } 1010 1011 String[] uidPackages = mContext.getPackageManager().getPackagesForUid(uid); 1012 if (uidPackages == null || uidPackages.length == 0) { 1013 // Failed to get uids for this package, can't validate package name. 1014 if (DEBUG) Log.d(TAG, "Failed to resolve package name"); 1015 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 1016 ProfilingResult.ERROR_UNKNOWN, null, tag, "Couldn't determine package name", 1017 getTriggerTypeNone()); 1018 return; 1019 } 1020 1021 boolean packageNameInUidList = false; 1022 for (int i = 0; i < uidPackages.length; i++) { 1023 if (packageName.equals(uidPackages[i])) { 1024 packageNameInUidList = true; 1025 break; 1026 } 1027 } 1028 if (!packageNameInUidList) { 1029 // Package name is not associated with calling uid, reject request. 1030 if (DEBUG) Log.d(TAG, "Package name not associated with calling uid"); 1031 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 1032 ProfilingResult.ERROR_FAILED_INVALID_REQUEST, null, tag, 1033 "Package name not associated with calling uid.", getTriggerTypeNone()); 1034 return; 1035 } 1036 1037 // Check with rate limiter if this request is allowed. 1038 final int status = getRateLimiter().isProfilingRequestAllowed(Binder.getCallingUid(), 1039 profilingType, false, params); 1040 if (DEBUG) Log.d(TAG, "Rate limiter status: " + status); 1041 if (status == RateLimiter.RATE_LIMIT_RESULT_ALLOWED) { 1042 // Rate limiter approved, try to start the request. 1043 try { 1044 TracingSession session = new TracingSession(profilingType, params, uid, 1045 packageName, tag, keyMostSigBits, keyLeastSigBits, getTriggerTypeNone()); 1046 advanceTracingSession(session, TracingState.APPROVED); 1047 return; 1048 } catch (IllegalArgumentException e) { 1049 // This should not happen, it should have been caught when checking rate limiter. 1050 // Issue with the request. Apps fault. 1051 if (DEBUG) { 1052 Log.d(TAG, 1053 "Invalid request at config generation. This should not have happened.", 1054 e); 1055 } 1056 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 1057 ProfilingResult.ERROR_FAILED_INVALID_REQUEST, null, tag, e.getMessage(), 1058 getTriggerTypeNone()); 1059 return; 1060 } catch (RuntimeException e) { 1061 // Perfetto error. Systems fault. 1062 if (DEBUG) Log.d(TAG, "Perfetto error", e); 1063 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 1064 ProfilingResult.ERROR_UNKNOWN, null, tag, "Perfetto error", 1065 getTriggerTypeNone()); 1066 return; 1067 } 1068 } else { 1069 // Rate limiter denied, notify caller. 1070 if (DEBUG) Log.d(TAG, "Request denied with status: " + status); 1071 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 1072 RateLimiter.statusToResult(status), null, tag, null, getTriggerTypeNone()); 1073 } 1074 } 1075 1076 /** 1077 * Convenience method to make checking the flag for obtaining trigger type none value in code 1078 * cleaner. When cleaning up the system triggered flag, remove this method and inline the value. 1079 */ getTriggerTypeNone()1080 private int getTriggerTypeNone() { 1081 if (Flags.systemTriggeredProfilingNew()) { 1082 return ProfilingTrigger.TRIGGER_TYPE_NONE; 1083 } 1084 return 0; 1085 } 1086 1087 /** Call from application to register a callback object. */ registerResultsCallback(boolean isGeneralCallback, IProfilingResultCallback callback)1088 public void registerResultsCallback(boolean isGeneralCallback, 1089 IProfilingResultCallback callback) { 1090 maybeCleanupResultsCallbacks(); 1091 1092 int callingUid = Binder.getCallingUid(); 1093 List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(callingUid); 1094 if (perUidCallbacks == null) { 1095 perUidCallbacks = new ArrayList<IProfilingResultCallback>(); 1096 mResultCallbacks.put(callingUid, perUidCallbacks); 1097 } 1098 perUidCallbacks.add(callback); 1099 1100 ProfilingDeathRecipient deathRecipient = new ProfilingDeathRecipient(callingUid); 1101 try { 1102 callback.asBinder().linkToDeath(deathRecipient, 0); 1103 } catch (RemoteException e) { 1104 // Failed to link death recipient. Ignore. 1105 if (DEBUG) Log.d(TAG, "Exception linking death recipient", e); 1106 } 1107 1108 // Only handle queued results when a new general listener has been added. 1109 if (isGeneralCallback) { 1110 handleQueuedResults(callingUid); 1111 } 1112 } 1113 1114 /** 1115 * Iterate through and delete any callbacks for which binder is not alive. 1116 * 1117 * Each binder object has a registered linkToDeath which also handles removal. This mechanism 1118 * serves as a backup to guarantee that the list stays in check. 1119 */ maybeCleanupResultsCallbacks()1120 private void maybeCleanupResultsCallbacks() { 1121 // Create a temporary list to hold callbacks to be removed. 1122 ArrayList<IProfilingResultCallback> callbacksToRemove = 1123 new ArrayList<IProfilingResultCallback>(); 1124 1125 // Iterate through the results callback, each iteration is for a uid which has registered 1126 // callbacks. 1127 for (int i = 0; i < mResultCallbacks.size(); i++) { 1128 // Ensure the temporary list is empty 1129 callbacksToRemove.clear(); 1130 1131 // Grab the current list of callbacks. 1132 List<IProfilingResultCallback> callbacks = mResultCallbacks.valueAt(i); 1133 1134 if (callbacks != null && !callbacks.isEmpty()) { 1135 // Now iterate through each of the callbacks for this uid. 1136 for (int j = 0; j < callbacks.size(); j++) { 1137 IProfilingResultCallback callback = callbacks.get(j); 1138 // If the callback is no longer alive, add it to the list for removal. 1139 if (callback == null || !callback.asBinder().isBinderAlive()) { 1140 callbacksToRemove.add(callback); 1141 } 1142 } 1143 1144 // Now remove all the callbacks that were added to the list for removal. 1145 callbacks.removeAll(callbacksToRemove); 1146 } 1147 } 1148 } 1149 1150 /** 1151 * Call from application to notify that a new global listener was added and can be accessed 1152 * through the existing callback object. 1153 */ generalListenerAdded()1154 public void generalListenerAdded() { 1155 handleQueuedResults(Binder.getCallingUid()); 1156 } 1157 1158 /** 1159 * Call from application to request the stopping of an active profiling with the provided key. 1160 */ requestCancel(long keyMostSigBits, long keyLeastSigBits)1161 public void requestCancel(long keyMostSigBits, long keyLeastSigBits) { 1162 String key = (new UUID(keyMostSigBits, keyLeastSigBits)).toString(); 1163 if (!isTraceRunning(key)) { 1164 // No trace running, nothing to cancel. 1165 if (DEBUG) { 1166 Log.d(TAG, "Exited requestCancel without stopping trace key:" + key 1167 + " due to no trace running."); 1168 } 1169 return; 1170 } 1171 stopProfiling(key); 1172 } 1173 1174 /** 1175 * Add the provided list of validated triggers with the provided package name and the callers 1176 * uid being applied to all. 1177 */ addProfilingTriggers(List<ProfilingTriggerValueParcel> triggers, String packageName)1178 public void addProfilingTriggers(List<ProfilingTriggerValueParcel> triggers, 1179 String packageName) { 1180 int uid = Binder.getCallingUid(); 1181 for (int i = 0; i < triggers.size(); i++) { 1182 ProfilingTriggerValueParcel trigger = triggers.get(i); 1183 addTrigger(uid, packageName, trigger.triggerType, trigger.rateLimitingPeriodHours); 1184 } 1185 } 1186 1187 /** 1188 * Remove the provided list of validated trigger codes from a process with the provided package 1189 * name and the uid of the caller. 1190 */ removeProfilingTriggers(int[] triggerTypesToRemove, String packageName)1191 public void removeProfilingTriggers(int[] triggerTypesToRemove, String packageName) { 1192 SparseArray<ProfilingTriggerData> triggers = 1193 mAppTriggers.get(packageName, Binder.getCallingUid()); 1194 1195 for (int i = 0; i < triggerTypesToRemove.length; i++) { 1196 int index = triggers.indexOfKey(triggerTypesToRemove[i]); 1197 if (index >= 0) { 1198 triggers.removeAt(index); 1199 } 1200 } 1201 1202 if (triggers.size() == 0) { 1203 // Nothing left, remove. 1204 mAppTriggers.remove(packageName, Binder.getCallingUid()); 1205 } 1206 } 1207 1208 /** 1209 * Remove all triggers from a process with the provided packagename and the uid of the caller. 1210 */ clearProfilingTriggers(String packageName)1211 public void clearProfilingTriggers(String packageName) { 1212 mAppTriggers.remove(packageName, Binder.getCallingUid()); 1213 } 1214 1215 /** 1216 * Method called by manager, after creating a file from within application context, to send a 1217 * file descriptor for service to write the result of the profiling session to. 1218 * 1219 * Note: only expected to be called in response to a generateFile request sent to manager. 1220 */ receiveFileDescriptor(ParcelFileDescriptor fileDescriptor, long keyMostSigBits, long keyLeastSigBits)1221 public void receiveFileDescriptor(ParcelFileDescriptor fileDescriptor, long keyMostSigBits, 1222 long keyLeastSigBits) { 1223 List<TracingSession> sessions = mQueuedTracingResults.get(Binder.getCallingUid()); 1224 if (sessions == null) { 1225 // No sessions for this uid, so no profiling result to write to this file descriptor. 1226 // Attempt to cleanup. 1227 finishReceiveFileDescriptor(null, fileDescriptor, null, null, false); 1228 return; 1229 } 1230 1231 TracingSession session = null; 1232 // Iterate through and try to find the session this file is associated with using the 1233 // key values. Key values were provided from the session to the generate file call that 1234 // triggered this. 1235 String key = (new UUID(keyMostSigBits, keyLeastSigBits)).toString(); 1236 for (int i = 0; i < sessions.size(); i++) { 1237 TracingSession tempSession = sessions.get(i); 1238 if (tempSession.getKey().equals(key)) { 1239 session = tempSession; 1240 break; 1241 } 1242 } 1243 if (session == null) { 1244 // No session for the provided key, nothing to do with this file descriptor. Attempt 1245 // to cleanup. 1246 finishReceiveFileDescriptor(session, fileDescriptor, null, null, false); 1247 return; 1248 } 1249 1250 // At this point we've identified the session that has sent us this file descriptor. 1251 // Now, we'll create a temporary file pointing to the profiling output for that session. 1252 // If that file looks good, we'll copy it to the app's local file descriptor. 1253 File tempResultFile = new File(TEMP_TRACE_PATH 1254 + (session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE 1255 ? session.getRedactedFileName() : session.getFileName())); 1256 FileInputStream tempPerfettoFileInStream = null; 1257 FileOutputStream appFileOutStream = null; 1258 1259 try { 1260 if (!tempResultFile.exists() || tempResultFile.length() == 0L) { 1261 // The profiling process output file does not exist or is empty, nothing to copy. 1262 if (DEBUG) { 1263 Log.d(TAG, "Temporary profiling output file is missing or empty, nothing to" 1264 + " copy."); 1265 } 1266 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 1267 appFileOutStream, false); 1268 return; 1269 } 1270 } catch (SecurityException e) { 1271 // If we hit a security exception checking file exists or size then we won't be able to 1272 // copy it, attempt to cleanup and return. 1273 if (DEBUG) { 1274 Log.d(TAG, "Exception checking if temporary file exists and is non-empty", e); 1275 } 1276 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 1277 appFileOutStream, false); 1278 return; 1279 } 1280 1281 // Setup file streams. 1282 try { 1283 tempPerfettoFileInStream = new FileInputStream(tempResultFile); 1284 } catch (IOException e) { 1285 // IO Exception opening temp perfetto file. No result. 1286 if (DEBUG) Log.d(TAG, "Exception opening temp perfetto file.", e); 1287 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 1288 appFileOutStream, false); 1289 return; 1290 } 1291 1292 // Obtain a file descriptor for the result file in app storage from 1293 // {@link ProfilingManager} 1294 if (fileDescriptor != null) { 1295 appFileOutStream = new FileOutputStream(fileDescriptor.getFileDescriptor()); 1296 } 1297 1298 if (appFileOutStream == null) { 1299 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 1300 appFileOutStream, false); 1301 return; 1302 } 1303 1304 // Now copy the file over. 1305 try { 1306 FileUtils.copy(tempPerfettoFileInStream, appFileOutStream); 1307 } catch (IOException e) { 1308 // Exception writing to local app file. Attempt to delete the bad copy. 1309 deleteBadCopiedFile(session); 1310 if (DEBUG) Log.d(TAG, "Exception writing to local app file.", e); 1311 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 1312 appFileOutStream, false); 1313 return; 1314 } 1315 1316 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 1317 appFileOutStream, true); 1318 } 1319 finishReceiveFileDescriptor(TracingSession session, ParcelFileDescriptor fileDescriptor, FileInputStream tempPerfettoFileInStream, FileOutputStream appFileOutStream, boolean succeeded)1320 private void finishReceiveFileDescriptor(TracingSession session, 1321 ParcelFileDescriptor fileDescriptor, FileInputStream tempPerfettoFileInStream, 1322 FileOutputStream appFileOutStream, boolean succeeded) { 1323 // Cleanup. 1324 if (tempPerfettoFileInStream != null) { 1325 try { 1326 tempPerfettoFileInStream.close(); 1327 } catch (IOException e) { 1328 if (DEBUG) Log.d(TAG, "Failed to close temp perfetto input stream.", e); 1329 } 1330 } 1331 if (fileDescriptor != null) { 1332 try { 1333 fileDescriptor.close(); 1334 } catch (IOException e) { 1335 if (DEBUG) Log.d(TAG, "Failed to close app file output file FileDescriptor.", e); 1336 } 1337 } 1338 if (appFileOutStream != null) { 1339 try { 1340 appFileOutStream.close(); 1341 } catch (IOException e) { 1342 if (DEBUG) Log.d(TAG, "Failed to close app file output file stream.", e); 1343 } 1344 } 1345 1346 if (session != null) { 1347 if (succeeded) { 1348 advanceTracingSession(session, TracingState.COPIED_FILE); 1349 } else { 1350 // Couldn't move file. File is still in temp directory and will be tried later. 1351 // Leave state unchanged so it can get triggered again from the queue, but update 1352 // the error and trigger a callback. 1353 if (DEBUG) Log.d(TAG, "Couldn't move file to app storage."); 1354 session.setError(ProfilingResult.ERROR_FAILED_POST_PROCESSING, 1355 "Failed to copy result to app storage. May try again later."); 1356 processTracingSessionResultCallback(session, false /* Do not continue */); 1357 } 1358 1359 // Clean up temporary directory if it has been long enough to warrant it. 1360 maybeCleanupTemporaryDirectory(); 1361 } 1362 } 1363 1364 /** 1365 * An app can register multiple callbacks between this service and {@link ProfilingManager}, one 1366 * per context that the app created a manager instance with. As we do not know on this service 1367 * side which callbacks need to be triggered with this result, trigger all of them and let them 1368 * decide whether to finish delivering it. 1369 * 1370 * Call this method if a {@link TracingSession} already exists. If no session exists yet, call 1371 * {@link #processResultCallback} directly instead. 1372 * 1373 * @param session The session for which to callback and potentially advance. 1374 * @param continueAdvancing Whether to continue advancing or stop after attempting the callback. 1375 */ 1376 @VisibleForTesting processTracingSessionResultCallback(TracingSession session, boolean continueAdvancing)1377 public void processTracingSessionResultCallback(TracingSession session, 1378 boolean continueAdvancing) { 1379 boolean succeeded = processResultCallback(session.getUid(), session.getKeyMostSigBits(), 1380 session.getKeyLeastSigBits(), session.getErrorStatus(), 1381 session.getDestinationFileName(OUTPUT_FILE_RELATIVE_PATH), 1382 session.getTag(), session.getErrorMessage(), session.getTriggerType()); 1383 1384 if (continueAdvancing && succeeded) { 1385 advanceTracingSession(session, TracingState.NOTIFIED_REQUESTER); 1386 } 1387 } 1388 1389 /** 1390 * An app can register multiple callbacks between this service and {@link ProfilingManager}, one 1391 * per context that the app created a manager instance with. As we do not know on this service 1392 * side which callbacks need to be triggered with this result, trigger all of them and let them 1393 * decide whether to finish delivering it. 1394 * 1395 * Call this directly only if no {@link TracingSession} exists yet. If a session already exists, 1396 * call {@link #processTracingSessionResultCallback} instead. 1397 * 1398 * @return whether at least one callback was successfully sent to the app. 1399 */ processResultCallback(int uid, long keyMostSigBits, long keyLeastSigBits, int status, @Nullable String fileResultPathAndName, @Nullable String tag, @Nullable String error, int triggerType)1400 private boolean processResultCallback(int uid, long keyMostSigBits, long keyLeastSigBits, 1401 int status, @Nullable String fileResultPathAndName, @Nullable String tag, 1402 @Nullable String error, int triggerType) { 1403 List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(uid); 1404 if (perUidCallbacks == null || perUidCallbacks.isEmpty()) { 1405 // No callbacks, nowhere to notify with result or failure. 1406 if (DEBUG) Log.d(TAG, "No callback to ProfilingManager, callback dropped."); 1407 return false; 1408 } 1409 1410 boolean succeeded = false; 1411 for (int i = 0; i < perUidCallbacks.size(); i++) { 1412 try { 1413 if (status == ProfilingResult.ERROR_NONE) { 1414 perUidCallbacks.get(i).sendResult( 1415 fileResultPathAndName, keyMostSigBits, keyLeastSigBits, status, tag, 1416 error, triggerType); 1417 } else { 1418 perUidCallbacks.get(i).sendResult( 1419 null, keyMostSigBits, keyLeastSigBits, status, tag, error, triggerType); 1420 } 1421 // One success is all we need to know that a callback was sent to the app. 1422 // This is not perfect but sufficient given we cannot verify the success of 1423 // individual listeners without either a blocking binder call into the app or an 1424 // extra binder call back from the app. 1425 succeeded = true; 1426 } catch (RemoteException e) { 1427 // Failed to send result. Ignore. 1428 if (DEBUG) Log.d(TAG, "Exception processing result callback", e); 1429 } 1430 } 1431 1432 return succeeded; 1433 } 1434 startProfiling(final TracingSession session)1435 private void startProfiling(final TracingSession session) 1436 throws RuntimeException { 1437 // Parse config and post processing delay out of request first, if we can't get these 1438 // we can't start the trace. 1439 int postProcessingInitialDelayMs; 1440 byte[] config; 1441 String suffix; 1442 String tag; 1443 try { 1444 postProcessingInitialDelayMs = session.getPostProcessingScheduleDelayMs(); 1445 config = session.getConfigBytes(); 1446 suffix = getFileSuffixForRequest(session.getProfilingType()); 1447 1448 // Create a version of tag that is non null, containing only valid filename chars, 1449 // and shortened to class defined max size. 1450 tag = session.getTag() == null 1451 ? "" : removeInvalidFilenameChars(session.getTag()); 1452 if (tag.length() > TAG_MAX_CHARS_FOR_FILENAME) { 1453 tag = tag.substring(0, TAG_MAX_CHARS_FOR_FILENAME); 1454 } 1455 } catch (IllegalArgumentException e) { 1456 // Request couldn't be processed. This shouldn't happen. 1457 if (DEBUG) Log.d(TAG, "Request couldn't be processed", e); 1458 session.setError(ProfilingResult.ERROR_FAILED_INVALID_REQUEST, e.getMessage()); 1459 // Don't bother adding the session to the queue as there is no real value in trying to 1460 // deliver this error callback again later in the case that the app no longer has a 1461 // registered listener. 1462 advanceTracingSession(session, TracingState.ERROR_OCCURRED); 1463 return; 1464 1465 } 1466 1467 String baseFileName = OUTPUT_FILE_PREFIX 1468 + (tag.isEmpty() ? "" : OUTPUT_FILE_SECTION_SEPARATOR + tag) 1469 + OUTPUT_FILE_SECTION_SEPARATOR + getFormattedDate(); 1470 1471 // Only trace files will go through the redaction process, set the name here for the file 1472 // that will be created later when results are processed. 1473 if (session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) { 1474 session.setRedactedFileName(baseFileName + OUTPUT_FILE_TRACE_SUFFIX); 1475 } 1476 1477 session.setFileName(baseFileName + suffix); 1478 1479 Process activeProfiling = startProfilingProcess(config, 1480 TEMP_TRACE_PATH + session.getFileName()); 1481 1482 if (activeProfiling != null) { 1483 // Profiling is running, save the session. 1484 session.setActiveTrace(activeProfiling); 1485 session.setProfilingStartTimeMs(System.currentTimeMillis()); 1486 mActiveTracingSessions.put(session.getKey(), session); 1487 } else { 1488 session.setError(ProfilingResult.ERROR_FAILED_EXECUTING, "Trace couldn't be started"); 1489 // Don't bother adding the session to the queue as there is no real value in trying to 1490 // deliver this error callback again later in the case that the app no longer has a 1491 // registered listener. 1492 advanceTracingSession(session, TracingState.ERROR_OCCURRED); 1493 return; 1494 } 1495 1496 // Create post process runnable, store it, and schedule it. 1497 session.setProcessResultRunnable(new Runnable() { 1498 @Override 1499 public void run() { 1500 // Check if the profiling process is complete or reschedule the check. 1501 checkProfilingCompleteRescheduleIfNeeded(session); 1502 } 1503 }); 1504 getHandler().postDelayed(session.getProcessResultRunnable(), postProcessingInitialDelayMs); 1505 1506 advanceTracingSession(session, TracingState.PROFILING_STARTED); 1507 } 1508 1509 /** 1510 * Start a trace to be used for system triggered profiling. 1511 * 1512 * This should not be called while a system triggered trace is already running. If it is called 1513 * with a system triggered trace in progress, this request will be dropped. 1514 */ 1515 @VisibleForTesting startSystemTriggeredTrace()1516 public void startSystemTriggeredTrace() { 1517 if (!Flags.systemTriggeredProfilingNew()) { 1518 // Flag disabled. 1519 return; 1520 } 1521 1522 if (!mAppTriggersLoaded) { 1523 // Until the triggers are loaded we can't create a proper config so just return. 1524 if (DEBUG) { 1525 Log.d(TAG, "System triggered trace not started due to app triggers not loaded."); 1526 } 1527 return; 1528 } 1529 1530 synchronized (mLock) { 1531 // Everything from the check if a system triggered trace is in progress to updating the 1532 // object to the new running trace should be in a single synchronized block to ensure 1533 // that another system triggered start is not attempted while one is in progress. 1534 1535 if (mSystemTriggeredTraceProcess != null && mSystemTriggeredTraceProcess.isAlive()) { 1536 // Only 1 system triggered trace should be running at a time. If one is already 1537 // running then this should not be called, return. 1538 if (DEBUG) { 1539 Log.d(TAG, "System triggered trace not started due to a system triggered trace " 1540 + "already in progress."); 1541 } 1542 return; 1543 } 1544 1545 String[] packageNames = getActiveTriggerPackageNames(); 1546 if (packageNames.length == 0) { 1547 // No apps have registered interest in system triggered profiling, so don't bother 1548 // to start a trace for it. 1549 if (DEBUG) { 1550 Log.d(TAG, "System triggered trace not started due to no apps registering " 1551 + "interest"); 1552 } 1553 return; 1554 } 1555 1556 String uniqueSessionName = SYSTEM_TRIGGERED_SESSION_NAME_PREFIX 1557 + System.currentTimeMillis(); 1558 1559 byte[] config = Configs.generateSystemTriggeredTraceConfig(uniqueSessionName, 1560 packageNames, 1561 mTestPackageName != null); 1562 String outputFile = TEMP_TRACE_PATH + SYSTEM_TRIGGERED_SESSION_NAME_PREFIX 1563 + OUTPUT_FILE_IN_PROGRESS + OUTPUT_FILE_UNREDACTED_TRACE_SUFFIX; 1564 1565 Process activeTrace = startProfilingProcess(config, outputFile); 1566 1567 if (activeTrace != null) { 1568 mSystemTriggeredTraceProcess = activeTrace; 1569 mSystemTriggeredTraceUniqueSessionName = uniqueSessionName; 1570 mLastStartedSystemTriggeredTraceMs = System.currentTimeMillis(); 1571 } 1572 } 1573 } 1574 1575 /** 1576 * Start the actual profiling process with necessary config details. 1577 * 1578 * @return the started process if it started successfully, or null if it failed to start. 1579 */ 1580 @Nullable startProfilingProcess(byte[] config, String outputFile)1581 private Process startProfilingProcess(byte[] config, String outputFile) { 1582 try { 1583 ProcessBuilder processBuilder = new ProcessBuilder("/system/bin/perfetto", "-o", 1584 outputFile, "-c", "-"); 1585 Process activeProfiling = processBuilder.start(); 1586 activeProfiling.getOutputStream().write(config); 1587 activeProfiling.getOutputStream().close(); 1588 return activeProfiling; 1589 } catch (Exception e) { 1590 // Catch all exceptions related to starting process as they'll all be handled similarly. 1591 if (DEBUG) Log.e(TAG, "Profiling couldn't be started", e); 1592 return null; 1593 } 1594 } 1595 1596 /** 1597 * Process a trigger for a uid + package name + trigger combination. This is done by verifying 1598 * that a trace is active, the app has registered interest in this combo, and that both system 1599 * and app provided rate limiting allow for it. If confirmed, it will proceed to clone the 1600 * active profiling and continue processing the result. 1601 * 1602 * Cloning will fork the running trace, stop the new forked trace, and output the result to a 1603 * separate file. This leaves the original trace running. 1604 */ processTrigger(int uid, @NonNull String packageName, int triggerType)1605 public void processTrigger(int uid, @NonNull String packageName, int triggerType) { 1606 if (!Flags.systemTriggeredProfilingNew()) { 1607 // Flag disabled. 1608 return; 1609 } 1610 1611 // Don't block the calling thread. 1612 getHandler().post(new Runnable() { 1613 @Override 1614 public void run() { 1615 processTriggerInternal(uid, packageName, triggerType); 1616 } 1617 }); 1618 } 1619 1620 /** 1621 * Internal call to process trigger, not to be called on the thread that passed the trigger in. 1622 */ 1623 @VisibleForTesting processTriggerInternal(int uid, @NonNull String packageName, int triggerType)1624 public void processTriggerInternal(int uid, @NonNull String packageName, int triggerType) { 1625 synchronized (mLock) { 1626 if (mSystemTriggeredTraceUniqueSessionName == null) { 1627 // If we don't have the session name then we don't know how to clone the trace so 1628 // stop it if it's still running and then return. 1629 stopSystemTriggeredTraceLocked(); 1630 1631 // There is no active system triggered trace so there's nothing to clone. Return. 1632 if (DEBUG) { 1633 Log.d(TAG, "Requested clone system triggered trace but we don't have the " 1634 + "session name."); 1635 } 1636 return; 1637 } 1638 1639 if (mSystemTriggeredTraceProcess == null || !mSystemTriggeredTraceProcess.isAlive()) { 1640 // If we make it to this path then session name wasn't set to null but can't be used 1641 // anymore as its associated trace is not running, so set to null now. 1642 mSystemTriggeredTraceUniqueSessionName = null; 1643 1644 // There is no active system triggered trace so there's nothing to clone. Return. 1645 if (DEBUG) { 1646 Log.d(TAG, "Requested clone system triggered trace but no trace active."); 1647 } 1648 return; 1649 } 1650 } 1651 1652 // Then check if the app has registered interest in this combo. 1653 SparseArray<ProfilingTriggerData> perProcessTriggers = mAppTriggers.get(packageName, uid); 1654 if (perProcessTriggers == null) { 1655 // This uid hasn't registered any triggers. 1656 if (DEBUG) { 1657 Log.d(TAG, String.format("Profiling triggered for uid %d with no registered " 1658 + "triggers", uid)); 1659 } 1660 return; 1661 } 1662 1663 ProfilingTriggerData trigger = perProcessTriggers.get(triggerType); 1664 if (trigger == null) { 1665 // This uid hasn't registered a trigger for this type. 1666 if (DEBUG) { 1667 Log.d(TAG, String.format("Profiling triggered for uid %d and trigger %d, but " 1668 + "app has not registered for this trigger type.", uid, triggerType)); 1669 } 1670 return; 1671 } 1672 1673 // Now apply system and app provided rate limiting. 1674 if (System.currentTimeMillis() - trigger.getLastTriggeredTimeMs() 1675 < trigger.getRateLimitingPeriodHours() * 60L * 60L * 1000L) { 1676 // App provided rate limiting doesn't allow for this run, return. 1677 if (DEBUG) { 1678 Log.d(TAG, String.format("Profiling triggered for uid %d and trigger %d but blocked" 1679 + " by app provided rate limiting ", uid, triggerType)); 1680 } 1681 return; 1682 } 1683 1684 // If this is from the test package, skip system rate limiting. 1685 if (!packageName.equals(mTestPackageName)) { 1686 int systemRateLimiterResult = getRateLimiter().isProfilingRequestAllowed(uid, 1687 ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE, true, null); 1688 if (systemRateLimiterResult != RateLimiter.RATE_LIMIT_RESULT_ALLOWED) { 1689 // Blocked by system rate limiter, return. Since this is system triggered there is 1690 // no callback and therefore no need to distinguish between per app and system 1691 // denials within the system rate limiter. 1692 if (DEBUG) { 1693 Log.d(TAG, String.format("Profiling triggered for uid %d and trigger %d but " 1694 + "blocked by system rate limiting ", uid, triggerType)); 1695 } 1696 return; 1697 } 1698 } 1699 1700 // Now that it's approved by both rate limiters, update their values. 1701 trigger.setLastTriggeredTimeMs(System.currentTimeMillis()); 1702 1703 // If we made it this far, a trace is running, the app has registered interest in this 1704 // trigger, and rate limiting allows for capturing the result. 1705 1706 // Create the file names 1707 String baseFileName = OUTPUT_FILE_PREFIX 1708 + OUTPUT_FILE_SECTION_SEPARATOR + OUTPUT_FILE_TRIGGER 1709 + OUTPUT_FILE_SECTION_SEPARATOR + triggerType 1710 + OUTPUT_FILE_SECTION_SEPARATOR + getFormattedDate(); 1711 String unredactedFullName = baseFileName + OUTPUT_FILE_UNREDACTED_TRACE_SUFFIX; 1712 1713 try { 1714 // Try to clone the running trace. 1715 Process clone = Runtime.getRuntime().exec(new String[] { 1716 "/system/bin/perfetto", 1717 "--clone-by-name", 1718 mSystemTriggeredTraceUniqueSessionName, 1719 "--out", 1720 TEMP_TRACE_PATH + unredactedFullName}); 1721 1722 // Wait for cloned process to stop. 1723 if (!clone.waitFor(mPerfettoDestroyTimeoutMs, TimeUnit.MILLISECONDS)) { 1724 // Cloned process did not stop, try to stop it forcibly. 1725 if (DEBUG) { 1726 Log.d(TAG, "Cloned system triggered trace didn't stop on its own, trying to " 1727 + "stop it forcibly."); 1728 } 1729 clone.destroyForcibly(); 1730 1731 // Wait again to see if it stops now. 1732 if (!clone.waitFor(mPerfettoDestroyTimeoutMs, TimeUnit.MILLISECONDS)) { 1733 // Nothing more to do, result won't be ready so return. 1734 if (DEBUG) Log.d(TAG, "Cloned system triggered trace timed out."); 1735 return; 1736 } 1737 } 1738 } catch (IOException | InterruptedException e) { 1739 // Failed. There's nothing to clean up as we haven't created a session for this clone 1740 // yet so just fail quietly. The result for this trigger instance combo will be lost. 1741 if (DEBUG) Log.d(TAG, "Failed to clone running system triggered trace.", e); 1742 return; 1743 } 1744 1745 // If we get here the clone was successful. Create a new TracingSession to track this and 1746 // continue moving it along the processing process. 1747 TracingSession session = new TracingSession( 1748 ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE, uid, packageName, triggerType); 1749 session.setRedactedFileName(baseFileName + OUTPUT_FILE_TRACE_SUFFIX); 1750 session.setFileName(unredactedFullName); 1751 session.setProfilingStartTimeMs(System.currentTimeMillis()); 1752 moveSessionToQueue(session, true); 1753 advanceTracingSession(session, TracingState.PROFILING_FINISHED); 1754 1755 maybePersistToDisk(); 1756 } 1757 1758 /** Add a profiling trigger to the supporting data structure. */ 1759 @VisibleForTesting addTrigger(int uid, @NonNull String packageName, int triggerType, int rateLimitingPeriodHours)1760 public void addTrigger(int uid, @NonNull String packageName, int triggerType, 1761 int rateLimitingPeriodHours) { 1762 addTrigger(new ProfilingTriggerData(uid, packageName, triggerType, rateLimitingPeriodHours), 1763 true); 1764 } 1765 1766 /** 1767 * Add a profiling trigger to the supporting data structure. 1768 * 1769 * @param trigger The trigger to add. 1770 * @param maybePersist Whether to persist to disk, if eligible based on frequency. This is 1771 * intended to be set to false only when loading triggers from disk. 1772 */ 1773 @VisibleForTesting addTrigger(ProfilingTriggerData trigger, boolean maybePersist)1774 public void addTrigger(ProfilingTriggerData trigger, boolean maybePersist) { 1775 if (!Flags.systemTriggeredProfilingNew()) { 1776 // Flag disabled. 1777 return; 1778 } 1779 1780 SparseArray<ProfilingTriggerData> perProcessTriggers = mAppTriggers.get( 1781 trigger.getPackageName(), trigger.getUid()); 1782 1783 if (perProcessTriggers == null) { 1784 perProcessTriggers = new SparseArray<ProfilingTriggerData>(); 1785 mAppTriggers.put(trigger.getPackageName(), trigger.getUid(), perProcessTriggers); 1786 } 1787 1788 // Only 1 trigger is allowed per uid + trigger type so this will override any previous 1789 // triggers of this type registered for this uid. 1790 perProcessTriggers.put(trigger.getTriggerType(), trigger); 1791 1792 if (maybePersist) { 1793 maybePersistToDisk(); 1794 } 1795 } 1796 1797 /** Get a list of all package names which have registered profiling triggers. */ getActiveTriggerPackageNames()1798 private String[] getActiveTriggerPackageNames() { 1799 // Since only system trace is supported for triggers, we can simply grab the key set of the 1800 // backing map for the ProcessMap which will contain all the package names. Once other 1801 // profiling types are supported, we'll need to filter these more intentionally to just the 1802 // ones that have an associated trace trigger. 1803 Set<String> packageNamesSet = mAppTriggers.getMap().keySet(); 1804 return packageNamesSet.toArray(new String[packageNamesSet.size()]); 1805 } 1806 1807 /** 1808 This method will check if the profiling subprocess is still alive. If it's still alive and 1809 there is still time permitted to run, another check will be scheduled. If the process is 1810 still alive but max allotted processing time has been exceeded, the profiling process will 1811 be stopped and results processed and returned to client. If the profiling process is 1812 complete results will be processed and returned to the client. 1813 */ checkProfilingCompleteRescheduleIfNeeded(TracingSession session)1814 private void checkProfilingCompleteRescheduleIfNeeded(TracingSession session) { 1815 long processingTimeRemaining = session.getMaxProfilingTimeAllowedMs() 1816 - (System.currentTimeMillis() - session.getProfilingStartTimeMs()); 1817 1818 if (session.getActiveTrace().isAlive() 1819 && processingTimeRemaining >= 0) { 1820 // still running and under max allotted processing time, reschedule the check. 1821 getHandler().postDelayed(session.getProcessResultRunnable(), 1822 Math.min(mProfilingRecheckDelayMs, processingTimeRemaining)); 1823 } else if (session.getActiveTrace().isAlive() 1824 && processingTimeRemaining < 0) { 1825 // still running but exceeded max allotted processing time, stop profiling and deliver 1826 // what results are available. 1827 stopProfiling(session.getKey()); 1828 } else { 1829 // complete, process results and deliver. 1830 session.setProcessResultRunnable(null); 1831 moveSessionToQueue(session, true); 1832 advanceTracingSession(session, TracingState.PROFILING_FINISHED); 1833 } 1834 } 1835 1836 /** Stop any active profiling sessions belonging to the provided uid. */ stopAllProfilingForUid(int uid)1837 private void stopAllProfilingForUid(int uid) { 1838 if (mActiveTracingSessions.isEmpty()) { 1839 // If there are no active traces, then there are none for this uid. 1840 return; 1841 } 1842 1843 // Iterate through active sessions and stop profiling if they belong to the provided uid. 1844 // Note: Currently, this will only ever have 1 session. 1845 for (int i = 0; i < mActiveTracingSessions.size(); i++) { 1846 TracingSession session = mActiveTracingSessions.valueAt(i); 1847 if (session.getUid() == uid) { 1848 stopProfiling(session); 1849 } 1850 } 1851 } 1852 1853 /** Stop active profiling for the given session key. */ stopProfiling(String key)1854 private void stopProfiling(String key) { 1855 TracingSession session = mActiveTracingSessions.get(key); 1856 stopProfiling(session); 1857 } 1858 1859 /** Stop active profiling for the given session. */ stopProfiling(TracingSession session)1860 private void stopProfiling(TracingSession session) { 1861 if (session == null || session.getActiveTrace() == null) { 1862 if (DEBUG) Log.d(TAG, "No active trace, nothing to stop."); 1863 return; 1864 } 1865 1866 if (session.getProcessResultRunnable() == null) { 1867 if (DEBUG) { 1868 Log.d(TAG, 1869 "No runnable, it either stopped already or is in the process of stopping."); 1870 } 1871 return; 1872 } 1873 1874 // Remove the post processing runnable set with the default timeout. After stopping use the 1875 // same runnable to process immediately. 1876 getHandler().removeCallbacks(session.getProcessResultRunnable()); 1877 1878 // End the tracing session. 1879 session.getActiveTrace().destroyForcibly(); 1880 try { 1881 if (!session.getActiveTrace().waitFor(mPerfettoDestroyTimeoutMs, 1882 TimeUnit.MILLISECONDS)) { 1883 if (DEBUG) Log.d(TAG, "Stopping of running trace process timed out."); 1884 return; 1885 } 1886 } catch (InterruptedException e) { 1887 if (DEBUG) Log.d(TAG, "Stopping of running trace error occurred.", e); 1888 return; 1889 } 1890 1891 // If we made it here the result is ready, now run the post processing runnable. 1892 getHandler().post(session.getProcessResultRunnable()); 1893 } 1894 1895 /** Check whether a profiling session is running. Not specific to any process. */ areAnyTracesRunning()1896 public boolean areAnyTracesRunning() throws RuntimeException { 1897 for (int i = 0; i < mActiveTracingSessions.size(); i++) { 1898 if (isTraceRunning(mActiveTracingSessions.keyAt(i))) { 1899 return true; 1900 } 1901 } 1902 return false; 1903 } 1904 1905 /** 1906 * Cleanup the data structure of active sessions. Non active sessions are never expected to be 1907 * present in {@link mActiveTracingSessions} as they would be moved to 1908 * {@link mQueuedTracingResults} when profiling completes. If a session is present but not 1909 * running, remove it. If a session has a not alive process, try to stop it. 1910 */ cleanupActiveTracingSessions()1911 public void cleanupActiveTracingSessions() throws RuntimeException { 1912 // Create a temporary list to store the keys of sessions to be stopped. 1913 ArrayList<String> sessionsToStop = new ArrayList<String>(); 1914 1915 // Iterate through in reverse order so we can immediately remove the non running sessions 1916 // that don't have to be stopped. 1917 for (int i = mActiveTracingSessions.size() - 1; i >= 0; i--) { 1918 String key = mActiveTracingSessions.keyAt(i); 1919 TracingSession session = mActiveTracingSessions.get(key); 1920 1921 if (session == null || session.getActiveTrace() == null) { 1922 // Profiling isn't running, remove from list. 1923 mActiveTracingSessions.removeAt(i); 1924 } else if (!session.getActiveTrace().isAlive()) { 1925 // Profiling process exists but isn't alive, add to list of sessions to stop. Do not 1926 // stop here due to potential unanticipated modification of list being iterated 1927 // through. 1928 sessionsToStop.add(key); 1929 } 1930 } 1931 1932 // If we have any sessions to stop, now is the time. 1933 if (!sessionsToStop.isEmpty()) { 1934 for (int i = 0; i < sessionsToStop.size(); i++) { 1935 stopProfiling(sessionsToStop.get(i)); 1936 } 1937 } 1938 } 1939 1940 /** Check whether a profiling session with the provided key is currently running. */ isTraceRunning(String key)1941 public boolean isTraceRunning(String key) throws RuntimeException { 1942 TracingSession session = mActiveTracingSessions.get(key); 1943 if (session == null || session.getActiveTrace() == null) { 1944 // No subprocess, nothing running. 1945 if (DEBUG) Log.d(TAG, "No subprocess, nothing running."); 1946 return false; 1947 } else if (session.getActiveTrace().isAlive()) { 1948 // Subprocess exists and is alive. 1949 if (DEBUG) Log.d(TAG, "Subprocess exists and is alive, trace is running."); 1950 return true; 1951 } else { 1952 // Subprocess exists but is not alive, nothing running. 1953 if (DEBUG) Log.d(TAG, "Subprocess exists but is not alive, nothing running."); 1954 return false; 1955 } 1956 } 1957 1958 /** 1959 * Begin moving result to storage by validating and then sending a request to 1960 * {@link ProfilingManager} for a file to write to. File will be returned as a 1961 * {@link ParcelFileDescriptor} via {@link sendFileDescriptor}. 1962 */ 1963 @VisibleForTesting beginMoveFileToAppStorage(TracingSession session)1964 public void beginMoveFileToAppStorage(TracingSession session) { 1965 if (session.getState().getValue() >= TracingState.ERROR_OCCURRED.getValue()) { 1966 // This should not have happened, if the session has a state of error or later then why 1967 // are we trying to continue processing it? Remove from all data stores just in case. 1968 if (DEBUG) { 1969 Log.d(TAG, "Attempted beginMoveFileToAppStorage on a session with status error" 1970 + " or an invalid status."); 1971 } 1972 mActiveTracingSessions.remove(session.getKey()); 1973 cleanupTracingSession(session); 1974 return; 1975 } 1976 1977 List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(session.getUid()); 1978 if (perUidCallbacks == null || perUidCallbacks.isEmpty()) { 1979 // No callback so no way to obtain a file to populate with result. 1980 if (DEBUG) Log.d(TAG, "No callback to ProfilingManager, callback dropped."); 1981 // TODO: b/333456916 run a cleanup of old results based on a max size and time. 1982 return; 1983 } 1984 1985 requestFileForResult(perUidCallbacks, session); 1986 } 1987 1988 /** 1989 * Delete a file which failed to copy via ProfilingManager. 1990 */ deleteBadCopiedFile(TracingSession session)1991 private void deleteBadCopiedFile(TracingSession session) { 1992 List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(session.getUid()); 1993 for (int i = 0; i < perUidCallbacks.size(); i++) { 1994 try { 1995 String fileName = 1996 session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE 1997 ? session.getRedactedFileName() : session.getFileName(); 1998 IProfilingResultCallback callback = perUidCallbacks.get(i); 1999 if (callback.asBinder().isBinderAlive()) { 2000 callback.deleteFile(OUTPUT_FILE_RELATIVE_PATH + fileName); 2001 // Only need one delete call, return. 2002 return; 2003 } 2004 } catch (RemoteException e) { 2005 // Binder exception deleting file. Continue trying other callbacks for this process. 2006 if (DEBUG) Log.d(TAG, "Binder exception deleting file. Trying next callback", e); 2007 } 2008 } 2009 } 2010 2011 /** 2012 * Request a {@link ParcelFileDescriptor} to a new file in app storage from the first live 2013 * callback for this uid. 2014 * 2015 * The new file is created by {@link ProfilingManager} from within app context. We only need a 2016 * single file, which can be created from any of the contexts belonging to the app that 2017 * requested this profiling, so it does not matter which of the requesting app's callbacks we 2018 * use. 2019 */ 2020 @Nullable requestFileForResult( @onNull List<IProfilingResultCallback> perUidCallbacks, TracingSession session)2021 private void requestFileForResult( 2022 @NonNull List<IProfilingResultCallback> perUidCallbacks, TracingSession session) { 2023 String fileName = session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE 2024 ? session.getRedactedFileName() 2025 : session.getFileName(); 2026 for (int i = 0; i < perUidCallbacks.size(); i++) { 2027 try { 2028 IProfilingResultCallback callback = perUidCallbacks.get(i); 2029 if (callback.asBinder().isBinderAlive()) { 2030 // Great, this one works! Call it and exit if we don't hit an exception. 2031 perUidCallbacks.get(i).generateFile(OUTPUT_FILE_RELATIVE_PATH, fileName, 2032 session.getKeyMostSigBits(), session.getKeyLeastSigBits()); 2033 return; 2034 } 2035 } catch (RemoteException e) { 2036 // Binder exception getting file. Continue trying other callbacks for this process. 2037 if (DEBUG) Log.d(TAG, "Binder exception getting file. Trying next callback", e); 2038 } 2039 } 2040 if (DEBUG) Log.d(TAG, "Failed to obtain file descriptor from callbacks."); 2041 } 2042 2043 /** Handle a result which required redaction by attempting to kick off redaction process. */ 2044 @VisibleForTesting handleRedactionRequiredResult(TracingSession session)2045 public void handleRedactionRequiredResult(TracingSession session) { 2046 try { 2047 // We need to create an empty file for the redaction process to write the output into. 2048 File emptyRedactedTraceFile = new File(TEMP_TRACE_PATH 2049 + session.getRedactedFileName()); 2050 emptyRedactedTraceFile.createNewFile(); 2051 } catch (Exception exception) { 2052 if (DEBUG) Log.e(TAG, "Creating empty redacted file failed.", exception); 2053 session.setError(ProfilingResult.ERROR_FAILED_POST_PROCESSING); 2054 advanceTracingSession(session, TracingState.ERROR_OCCURRED); 2055 return; 2056 } 2057 2058 try { 2059 // Start the redaction process and log the time of start. Redaction has 2060 // mRedactionMaxRuntimeAllottedMs to complete. Redaction status will be checked every 2061 // mRedactionCheckFrequencyMs. 2062 ProcessBuilder redactionProcess = new ProcessBuilder( 2063 "/apex/com.android.profiling/bin/trace_redactor", 2064 TEMP_TRACE_PATH + session.getFileName(), 2065 TEMP_TRACE_PATH + session.getRedactedFileName(), 2066 session.getPackageName()); 2067 session.setActiveRedaction(redactionProcess.start()); 2068 session.setRedactionStartTimeMs(System.currentTimeMillis()); 2069 } catch (Exception exception) { 2070 if (DEBUG) Log.e(TAG, "Redaction failed to run completely.", exception); 2071 session.setError(ProfilingResult.ERROR_FAILED_POST_PROCESSING); 2072 advanceTracingSession(session, TracingState.ERROR_OCCURRED); 2073 return; 2074 } 2075 2076 session.setProcessResultRunnable(new Runnable() { 2077 2078 @Override 2079 public void run() { 2080 checkRedactionStatus(session); 2081 } 2082 }); 2083 getHandler().postDelayed(session.getProcessResultRunnable(), 2084 mRedactionCheckFrequencyMs); 2085 } 2086 checkRedactionStatus(TracingSession session)2087 private void checkRedactionStatus(TracingSession session) { 2088 // Check if redaction is complete. 2089 if (!session.getActiveRedaction().isAlive()) { 2090 handleRedactionComplete(session); 2091 session.setProcessResultRunnable(null); 2092 return; 2093 } 2094 2095 // Check if we are over the mRedactionMaxRuntimeAllottedMs threshold. 2096 if ((System.currentTimeMillis() - session.getRedactionStartTimeMs()) 2097 > mRedactionMaxRuntimeAllottedMs) { 2098 if (DEBUG) Log.d(TAG, "Redaction process has timed out"); 2099 2100 session.getActiveRedaction().destroyForcibly(); 2101 session.setProcessResultRunnable(null); 2102 session.setError(ProfilingResult.ERROR_FAILED_POST_PROCESSING); 2103 advanceTracingSession(session, TracingState.ERROR_OCCURRED); 2104 return; 2105 } 2106 2107 // Schedule the next check. 2108 getHandler().postDelayed(session.getProcessResultRunnable(), 2109 Math.min(mRedactionCheckFrequencyMs, mRedactionMaxRuntimeAllottedMs 2110 - (System.currentTimeMillis() - session.getRedactionStartTimeMs()))); 2111 2112 } 2113 handleRedactionComplete(TracingSession session)2114 private void handleRedactionComplete(TracingSession session) { 2115 int redactionErrorCode = session.getActiveRedaction().exitValue(); 2116 if (redactionErrorCode != 0) { 2117 // Redaction process failed. This failure cannot be recovered. 2118 if (DEBUG) { 2119 Log.d(TAG, String.format("Redaction processed failed with error code: %s", 2120 redactionErrorCode)); 2121 } 2122 session.setError(ProfilingResult.ERROR_FAILED_POST_PROCESSING); 2123 advanceTracingSession(session, TracingState.ERROR_OCCURRED); 2124 return; 2125 } 2126 2127 // At this point redaction has completed successfully it is safe to delete the 2128 // unredacted trace file unless {@link mKeepResultInTempDir} has been enabled. 2129 synchronized (mLock) { 2130 if (!mKeepResultInTempDir) { 2131 deleteProfilingFiles(session, 2132 false, /* Don't delete the newly redacted file */ 2133 true); /* Do delete the no longer needed unredacted file.*/ 2134 } 2135 } 2136 2137 advanceTracingSession(session, TracingState.REDACTED); 2138 } 2139 2140 /** 2141 * Handle retained temporary files due to {@link mKeepResultInTempDir} being enabled, by 2142 * attempting to make them publicly readable and logging their location 2143 */ handleRetainedTempFiles(TracingSession session)2144 private void handleRetainedTempFiles(TracingSession session) { 2145 synchronized (mLock) { 2146 if (!mKeepResultInTempDir) { 2147 // Results are only retained if {@link mKeepResultInTempDir} is enabled, so don't 2148 // log the locations if it's disabled. 2149 return; 2150 } 2151 2152 // For all types, output the location of the original profiling output file. For trace, 2153 // this will be the unredacted copy. For all other types, this will be the only output 2154 // file. 2155 boolean makeReadableSucceeded = makeFileReadable(session.getFileName()); 2156 logRetainedFileDetails(session.getFileName(), makeReadableSucceeded); 2157 2158 if (session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) { 2159 // For a trace, output the location of the redacted file. 2160 makeReadableSucceeded = makeFileReadable(session.getRedactedFileName()); 2161 logRetainedFileDetails(session.getFileName(), makeReadableSucceeded); 2162 } 2163 } 2164 } 2165 2166 /** Wrapper to log all necessary information about retained file locations. */ logRetainedFileDetails(String fileName, boolean readable)2167 private void logRetainedFileDetails(String fileName, boolean readable) { 2168 if (readable) { 2169 Log.i(TAG, "Profiling file retained at: " + TEMP_TRACE_PATH + fileName); 2170 } else { 2171 Log.i(TAG, "Profiling file retained at: " + TEMP_TRACE_PATH + fileName 2172 + " | File is not publicly accessible, root access is required to read."); 2173 } 2174 } 2175 2176 /** 2177 * Make the provided file within the temp trace directory publicly readable. Access is still 2178 * limited by selinux so only adbd will be additionally able to access the file due to this 2179 * change. 2180 * 2181 * @return whether making the file readable succeeded. 2182 */ 2183 @SuppressWarnings("SetWorldReadable") makeFileReadable(String fileName)2184 private boolean makeFileReadable(String fileName) { 2185 try { 2186 File file = new File(TEMP_TRACE_PATH + fileName); 2187 return file.setReadable(true, false); 2188 } catch (Exception e) { 2189 Log.w(TAG, "Failed to make file readable for testing.", e); 2190 return false; 2191 } 2192 } 2193 2194 /** 2195 * Called whenever a new global listener has been added to the specified uid. 2196 * Attempts to process queued results if present. 2197 */ 2198 @VisibleForTesting handleQueuedResults(int uid)2199 public void handleQueuedResults(int uid) { 2200 List<TracingSession> queuedSessions = mQueuedTracingResults.get(uid); 2201 if (queuedSessions == null || queuedSessions.isEmpty()) { 2202 // No queued results for this uid, nothing to handle. Attempt to cleanup the queue for 2203 // all other uids before exiting. 2204 maybeCleanupQueue(); 2205 return; 2206 } 2207 2208 // Triggering the callbacks may result in the object being removed from the class level 2209 // queue list, ensure this remains safe by using a unmodifiable shallow copy of the list. 2210 List<TracingSession> unmodifiableQueuedSessions = List.copyOf(queuedSessions); 2211 for (int i = 0; i < unmodifiableQueuedSessions.size(); i++) { 2212 TracingSession session = unmodifiableQueuedSessions.get(i); 2213 2214 // Check if we already retried too many times and discard the result if we have. 2215 if (session.getRetryCount() >= mMaxResultRedeliveryCount) { 2216 cleanupTracingSession(session, queuedSessions); 2217 continue; 2218 } 2219 session.incrementRetryCount(); 2220 2221 // Advance with new state null so that it picks up where it left off. 2222 advanceTracingSession(session, null); 2223 } 2224 2225 // Now attempt to cleanup the queue. 2226 maybeCleanupQueue(); 2227 } 2228 2229 /** Run through all queued sessions and clean up the ones that are too old. */ maybeCleanupQueue()2230 private void maybeCleanupQueue() { 2231 List<TracingSession> sessionsToRemove = new ArrayList(); 2232 // Iterate in reverse so we can remove the index if empty. 2233 for (int i = mQueuedTracingResults.size() - 1; i >= 0; i--) { 2234 List<TracingSession> sessions = mQueuedTracingResults.valueAt(i); 2235 if (sessions != null && !sessions.isEmpty()) { 2236 sessionsToRemove.clear(); 2237 for (int j = 0; j < sessions.size(); j++) { 2238 TracingSession session = sessions.get(j); 2239 if (session.getProfilingStartTimeMs() + QUEUED_RESULT_MAX_RETAINED_DURATION_MS 2240 < System.currentTimeMillis()) { 2241 cleanupTracingSession(session); 2242 sessionsToRemove.add(session); 2243 } 2244 } 2245 sessions.removeAll(sessionsToRemove); 2246 if (sessions.isEmpty()) { 2247 mQueuedTracingResults.removeAt(i); 2248 } 2249 } else { 2250 mQueuedTracingResults.removeAt(i); 2251 } 2252 } 2253 } 2254 2255 /** 2256 * Cleanup is intended for when we're done with a queued trace session, whether successful or 2257 * not. 2258 * 2259 * Cleanup will attempt to delete the temporary file(s) and then remove it from the queue. 2260 */ 2261 @VisibleForTesting cleanupTracingSession(TracingSession session)2262 public void cleanupTracingSession(TracingSession session) { 2263 List<TracingSession> queuedSessions = mQueuedTracingResults.get(session.getUid()); 2264 cleanupTracingSession(session, queuedSessions); 2265 } 2266 2267 /** 2268 * Cleanup is intended for when we're done with a queued trace session, whether successful or 2269 * not. 2270 * 2271 * Cleanup will attempt to delete the temporary file(s) and then remove it from the queue. 2272 */ cleanupTracingSession(TracingSession session, @Nullable List<TracingSession> queuedSessions)2273 private void cleanupTracingSession(TracingSession session, 2274 @Nullable List<TracingSession> queuedSessions) { 2275 synchronized (mLock) { 2276 if (mKeepResultInTempDir) { 2277 // If {@link mKeepResultInTempDir} is enabled, don't cleanup anything. Continue 2278 // progressing as if cleanup is complete. 2279 advanceTracingSession(session, TracingState.CLEANED_UP); 2280 return; 2281 } 2282 } 2283 2284 // Delete all files 2285 deleteProfilingFiles(session, true, true); 2286 2287 if (queuedSessions != null) { 2288 queuedSessions.remove(session); 2289 if (queuedSessions.isEmpty()) { 2290 mQueuedTracingResults.remove(session.getUid()); 2291 } 2292 } 2293 2294 advanceTracingSession(session, TracingState.CLEANED_UP); 2295 } 2296 2297 /** 2298 * Attempt to delete profiling output. 2299 * 2300 * If both boolean params are false, this method expectedly does nothing. 2301 * 2302 * @param deleteRedacted Whether to delete the redacted file. 2303 * @param deleteUnredacted Whether to delete the unredacted file. 2304 */ deleteProfilingFiles(TracingSession session, boolean deleteRedacted, boolean deleteUnredacted)2305 private void deleteProfilingFiles(TracingSession session, boolean deleteRedacted, 2306 boolean deleteUnredacted) { 2307 if (deleteRedacted) { 2308 try { 2309 Files.deleteIfExists(Path.of(TEMP_TRACE_PATH + session.getRedactedFileName())); 2310 } catch (Exception exception) { 2311 if (DEBUG) Log.e(TAG, "Failed to delete file.", exception); 2312 } 2313 } 2314 2315 if (deleteUnredacted) { 2316 try { 2317 Files.deleteIfExists(Path.of(TEMP_TRACE_PATH + session.getFileName())); 2318 } catch (Exception exception) { 2319 if (DEBUG) Log.e(TAG, "Failed to delete file.", exception); 2320 } 2321 } 2322 } 2323 2324 /** 2325 * Move session to list of queued sessions. Removes the session from the list of active 2326 * sessions, if it is present. 2327 * 2328 * Sessions are expected to be in the queue when their states are between PROFILING_FINISHED and 2329 * NOTIFIED_REQUESTER, inclusive. 2330 * 2331 * Sessions should only be added to the queue with a valid profiling start time. Sessions added 2332 * without a valid start time may be cleaned up in middle of their execution and fail to deliver 2333 * any result. 2334 * 2335 * @param session the session to move to the queue 2336 * @param maybePersist whether to persist the queue to disk if the queue is eligible to be 2337 * persisted 2338 */ moveSessionToQueue(TracingSession session, boolean maybePersist)2339 private void moveSessionToQueue(TracingSession session, boolean maybePersist) { 2340 if (DEBUG && session.getProfilingStartTimeMs() == 0) { 2341 Log.e(TAG, "Attempting to move session to queue without a start time set.", 2342 new Throwable()); 2343 } 2344 2345 List<TracingSession> queuedResults = mQueuedTracingResults.get(session.getUid()); 2346 if (queuedResults == null) { 2347 queuedResults = new ArrayList<TracingSession>(); 2348 mQueuedTracingResults.put(session.getUid(), queuedResults); 2349 } 2350 queuedResults.add(session); 2351 mActiveTracingSessions.remove(session.getKey()); 2352 2353 if (maybePersist) { 2354 maybePersistToDisk(); 2355 } 2356 } 2357 needsRedaction(TracingSession session)2358 private boolean needsRedaction(TracingSession session) { 2359 return session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE; 2360 } 2361 getHandler()2362 private Handler getHandler() { 2363 if (mHandler == null) { 2364 mHandler = new Handler(mHandlerThread.getLooper()); 2365 } 2366 return mHandler; 2367 } 2368 getRateLimiter()2369 private RateLimiter getRateLimiter() { 2370 if (mRateLimiter == null) { 2371 mRateLimiter = new RateLimiter(new RateLimiter.HandlerCallback() { 2372 @Override 2373 public Handler obtainHandler() { 2374 return getHandler(); 2375 } 2376 }); 2377 } 2378 return mRateLimiter; 2379 } 2380 getFormattedDate()2381 private String getFormattedDate() { 2382 if (mCalendar == null) { 2383 mCalendar = Calendar.getInstance(TimeZone.getTimeZone("GMT")); 2384 } 2385 if (mDateFormat == null) { 2386 mDateFormat = new SimpleDateFormat("yyyy-MM-dd-HH-mm-ss", Locale.US); 2387 } 2388 mCalendar.setTimeInMillis(System.currentTimeMillis()); 2389 return mDateFormat.format(mCalendar.getTime()); 2390 } 2391 getFileSuffixForRequest(int profilingType)2392 private static String getFileSuffixForRequest(int profilingType) { 2393 switch (profilingType) { 2394 case ProfilingManager.PROFILING_TYPE_JAVA_HEAP_DUMP: 2395 return OUTPUT_FILE_JAVA_HEAP_DUMP_SUFFIX; 2396 case ProfilingManager.PROFILING_TYPE_HEAP_PROFILE: 2397 return OUTPUT_FILE_HEAP_PROFILE_SUFFIX; 2398 case ProfilingManager.PROFILING_TYPE_STACK_SAMPLING: 2399 return OUTPUT_FILE_STACK_SAMPLING_SUFFIX; 2400 case ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE: 2401 return OUTPUT_FILE_UNREDACTED_TRACE_SUFFIX; 2402 default: 2403 throw new IllegalArgumentException("Invalid profiling type"); 2404 } 2405 } 2406 removeInvalidFilenameChars(String original)2407 private static String removeInvalidFilenameChars(String original) { 2408 if (TextUtils.isEmpty(original)) { 2409 return ""; 2410 } 2411 final StringBuilder sb = new StringBuilder(original.length()); 2412 for (int i = 0; i < original.length(); i++) { 2413 final char c = Character.toLowerCase(original.charAt(i)); 2414 if (isValidFilenameChar(c)) { 2415 sb.append(c); 2416 } 2417 } 2418 return sb.toString(); 2419 } 2420 isValidFilenameChar(char c)2421 private static boolean isValidFilenameChar(char c) { 2422 if (c >= 'a' && c <= 'z') { 2423 return true; 2424 } 2425 if (c >= '0' && c <= '9') { 2426 return true; 2427 } 2428 if (c == '-') { 2429 return true; 2430 } 2431 return false; 2432 } 2433 2434 /** 2435 * Persist service data to disk following the following rules: 2436 * - If a persist is already scheduled, do nothing. 2437 * - If a persist happened within the last {@link #mPersistFrequencyMs} then schedule a 2438 * persist for {@link #mPersistFrequencyMs} after the last persist. 2439 * - If no persist has occurred yet or the most recent persist was more than 2440 * {@link #mPersistFrequencyMs} ago, persist immediately. 2441 */ 2442 @VisibleForTesting maybePersistToDisk()2443 public void maybePersistToDisk() { 2444 if (!Flags.persistQueue() && !Flags.systemTriggeredProfilingNew()) { 2445 // No persisting is enabled. 2446 return; 2447 } 2448 2449 synchronized (mLock) { 2450 if (mPersistScheduled) { 2451 // We're already waiting on a scheduled persist job, do nothing. 2452 return; 2453 } 2454 2455 if (mPersistFrequencyMs.get() != 0 2456 && (System.currentTimeMillis() - mLastPersistedTimestampMs 2457 < mPersistFrequencyMs.get())) { 2458 // Schedule the persist job. 2459 if (mPersistRunnable == null) { 2460 mPersistRunnable = new Runnable() { 2461 @Override 2462 public void run() { 2463 if (Flags.persistQueue()) { 2464 persistQueueToDisk(); 2465 } 2466 if (Flags.systemTriggeredProfilingNew()) { 2467 persistAppTriggersToDisk(); 2468 } 2469 mPersistScheduled = false; 2470 } 2471 }; 2472 } 2473 mPersistScheduled = true; 2474 long persistDelay = mLastPersistedTimestampMs + mPersistFrequencyMs.get() 2475 - System.currentTimeMillis(); 2476 getHandler().postDelayed(mPersistRunnable, persistDelay); 2477 return; 2478 } 2479 } 2480 2481 // If we got here then either persist frequency is 0 or it has already been longer than 2482 // persist frequency since the last persist. Persist immediately. 2483 if (Flags.persistQueue()) { 2484 persistQueueToDisk(); 2485 } 2486 if (Flags.systemTriggeredProfilingNew()) { 2487 persistAppTriggersToDisk(); 2488 } 2489 } 2490 2491 /** Persist the current queue to disk after cleaning it up. */ 2492 @VisibleForTesting persistQueueToDisk()2493 public void persistQueueToDisk() { 2494 if (!Flags.persistQueue()) { 2495 return; 2496 } 2497 2498 // Check if file exists 2499 try { 2500 if (mPersistQueueFile == null) { 2501 // Try again to create the necessary files. 2502 if (!setupPersistQueueFiles()) { 2503 // No file, nowhere to save. 2504 if (DEBUG) { 2505 Log.d(TAG, "Failed setting up queue persist files so nowhere to save to."); 2506 } 2507 return; 2508 } 2509 } 2510 2511 if (!mPersistQueueFile.exists()) { 2512 // File doesn't exist, try to create it. 2513 mPersistQueueFile.createNewFile(); 2514 } 2515 } catch (Exception e) { 2516 if (DEBUG) Log.e(TAG, "Exception accessing persisted records store.", e); 2517 return; 2518 } 2519 2520 // Clean up queue to reduce extraneous writes 2521 maybeCleanupQueue(); 2522 2523 // Generate proto for queue. 2524 QueuedResultsWrapper.Builder builder = QueuedResultsWrapper.newBuilder(); 2525 2526 boolean recordAdded = false; 2527 2528 for (int i = 0; i < mQueuedTracingResults.size(); i++) { 2529 List<TracingSession> perUidSessions = mQueuedTracingResults.valueAt(i); 2530 if (!perUidSessions.isEmpty()) { 2531 for (int j = 0; j < perUidSessions.size(); j++) { 2532 builder.addSessions(perUidSessions.get(j).toProto()); 2533 2534 if (!recordAdded) { 2535 recordAdded = true; 2536 } 2537 } 2538 } 2539 } 2540 2541 if (!recordAdded) { 2542 // No results, nothing to persist, delete the file as it may contain results that are no 2543 // longer meaningful and will just increase future work and then return. 2544 deletePersistQueueFile(); 2545 return; 2546 } 2547 2548 QueuedResultsWrapper queuedResultsWrapper = builder.build(); 2549 2550 // Write to disk 2551 byte[] protoBytes = queuedResultsWrapper.toByteArray(); 2552 AtomicFile persistFile = new AtomicFile(mPersistQueueFile); 2553 FileOutputStream out = null; 2554 try { 2555 out = persistFile.startWrite(); 2556 out.write(protoBytes); 2557 persistFile.finishWrite(out); 2558 synchronized (mLock) { 2559 mLastPersistedTimestampMs = System.currentTimeMillis(); 2560 } 2561 } catch (IOException e) { 2562 if (DEBUG) Log.e(TAG, "Exception writing queued results", e); 2563 persistFile.failWrite(out); 2564 } 2565 } 2566 2567 /** Persist the current app triggers to disk. */ 2568 @VisibleForTesting persistAppTriggersToDisk()2569 public void persistAppTriggersToDisk() { 2570 // Check if file exists 2571 try { 2572 if (mPersistAppTriggersFile == null) { 2573 // Try again to create the necessary files. 2574 if (!setupPersistAppTriggerFiles()) { 2575 // No file, nowhere to save. 2576 if (DEBUG) { 2577 Log.d(TAG, "Failed setting up app triggers persist files so nowhere to save" 2578 + " to."); 2579 } 2580 return; 2581 } 2582 } 2583 2584 if (!mPersistAppTriggersFile.exists()) { 2585 // File doesn't exist, try to create it. 2586 mPersistAppTriggersFile.createNewFile(); 2587 } 2588 } catch (Exception e) { 2589 if (DEBUG) Log.e(TAG, "Exception accessing persisted app triggers store.", e); 2590 return; 2591 } 2592 2593 // Generate proto for queue. 2594 ProfilingTriggersWrapper.Builder builder = ProfilingTriggersWrapper.newBuilder(); 2595 2596 forEachTrigger(mAppTriggers.getMap(), (trigger) -> builder.addTriggers(trigger.toProto())); 2597 2598 ProfilingTriggersWrapper queuedTriggersWrapper = builder.build(); 2599 2600 // Write to disk 2601 byte[] protoBytes = queuedTriggersWrapper.toByteArray(); 2602 AtomicFile persistFile = new AtomicFile(mPersistAppTriggersFile); 2603 FileOutputStream out = null; 2604 try { 2605 out = persistFile.startWrite(); 2606 out.write(protoBytes); 2607 persistFile.finishWrite(out); 2608 synchronized (mLock) { 2609 mLastPersistedTimestampMs = System.currentTimeMillis(); 2610 } 2611 } catch (IOException e) { 2612 if (DEBUG) Log.e(TAG, "Exception writing app triggers", e); 2613 persistFile.failWrite(out); 2614 } 2615 } 2616 2617 /** Receive a callback with each of the tracked profiling triggers. */ forEachTrigger( ArrayMap<String, SparseArray<SparseArray<ProfilingTriggerData>>> triggersOuterMap, Consumer<ProfilingTriggerData> callback)2618 private void forEachTrigger( 2619 ArrayMap<String, SparseArray<SparseArray<ProfilingTriggerData>>> triggersOuterMap, 2620 Consumer<ProfilingTriggerData> callback) { 2621 2622 for (int i = 0; i < triggersOuterMap.size(); i++) { 2623 SparseArray<SparseArray<ProfilingTriggerData>> triggerUidList = 2624 triggersOuterMap.valueAt(i); 2625 2626 for (int j = 0; j < triggerUidList.size(); j++) { 2627 int uidKey = triggerUidList.keyAt(j); 2628 SparseArray<ProfilingTriggerData> triggersList = triggerUidList.get(uidKey); 2629 2630 if (triggersList != null) { 2631 for (int k = 0; k < triggersList.size(); k++) { 2632 int triggerTypeKey = triggersList.keyAt(k); 2633 ProfilingTriggerData trigger = triggersList.get(triggerTypeKey); 2634 2635 if (trigger != null) { 2636 callback.accept(trigger); 2637 } 2638 } 2639 } 2640 } 2641 } 2642 } 2643 2644 /** Handle updates to test package config value. */ 2645 @GuardedBy("mLock") handleTestPackageChangeLocked(String newTestPackageName)2646 private void handleTestPackageChangeLocked(String newTestPackageName) { 2647 if (newTestPackageName == null) { 2648 2649 // Test package has been set to null, check whether it was null previously. 2650 if (mTestPackageName != null) { 2651 2652 // New null state is a changed from previous state, disable test mode. 2653 mTestPackageName = null; 2654 stopSystemTriggeredTraceLocked(); 2655 } 2656 // If new state is unchanged from previous null state, do nothing. 2657 } else { 2658 2659 // Test package has been set with a value. Stop running system triggered trace if 2660 // applicable so we can start a new one that will have most up to date package names. 2661 // This should not be called when the new test package name matches the old one as 2662 // device config should not be sending an update for a value change when the value 2663 // remains the same, but no need to check as the best experience for caller is to always 2664 // stop the current trace and start a new one for most up to date package list. 2665 stopSystemTriggeredTraceLocked(); 2666 2667 // Now update the test package name and start the system triggered trace. 2668 mTestPackageName = newTestPackageName; 2669 startSystemTriggeredTrace(); 2670 } 2671 } 2672 2673 /** 2674 * Stop the system triggered trace. 2675 * 2676 * Locked because {link mSystemTriggeredTraceProcess} is guarded and all callers are already 2677 * locked. 2678 */ 2679 @GuardedBy("mLock") stopSystemTriggeredTraceLocked()2680 private void stopSystemTriggeredTraceLocked() { 2681 // If the trace is alive, stop it. 2682 if (mSystemTriggeredTraceProcess != null) { 2683 if (mSystemTriggeredTraceProcess.isAlive()) { 2684 mSystemTriggeredTraceProcess.destroyForcibly(); 2685 } 2686 mSystemTriggeredTraceProcess = null; 2687 } 2688 2689 // Set session name to null. 2690 mSystemTriggeredTraceUniqueSessionName = null; 2691 } 2692 2693 private class ProfilingDeathRecipient implements IBinder.DeathRecipient { 2694 private final int mUid; 2695 ProfilingDeathRecipient(int uid)2696 ProfilingDeathRecipient(int uid) { 2697 mUid = uid; 2698 } 2699 2700 @Override binderDied()2701 public void binderDied() { 2702 if (DEBUG) Log.d(TAG, "binderDied without who should not have been called"); 2703 } 2704 2705 @Override binderDied(IBinder who)2706 public void binderDied(IBinder who) { 2707 // Synchronize because multiple binder died callbacks may occur simultaneously 2708 // on different threads and we want to ensure that when an app dies (i.e. all 2709 // binder objects die) we attempt to stop profiling exactly once. 2710 synchronized (mLock) { 2711 List<IProfilingResultCallback> callbacks = mResultCallbacks.get(mUid); 2712 2713 if (callbacks == null) { 2714 // No callbacks list for this uid, this likely means profiling was already 2715 // stopped (i.e. this is not the first binderDied call for this death). 2716 return; 2717 } 2718 2719 // Callbacks aren't valid anymore, remove the list. 2720 mResultCallbacks.remove(mUid); 2721 2722 // Finally, attempt to stop profiling. Once the profiling is stopped, processing 2723 // will continue as usual and will fail at copy to app storage which is the next 2724 // step that requires the now dead binder objects. The failure will result in the 2725 // session being added to {@link mQueueTracingResults} and being delivered to the 2726 // app the next time it registers a general listener. 2727 stopAllProfilingForUid(mUid); 2728 } 2729 } 2730 } 2731 2732 public static final class Lifecycle extends SystemService { 2733 final ProfilingService mService; 2734 Lifecycle(Context context)2735 public Lifecycle(Context context) { 2736 this(context, new ProfilingService(context)); 2737 } 2738 2739 @VisibleForTesting Lifecycle(Context context, ProfilingService service)2740 public Lifecycle(Context context, ProfilingService service) { 2741 super(context); 2742 mService = service; 2743 } 2744 2745 @Override onStart()2746 public void onStart() { 2747 try { 2748 publishBinderService("profiling_service", mService); 2749 } catch (Exception e) { 2750 if (DEBUG) Log.d(TAG, "Failed to publish service", e); 2751 } 2752 } 2753 2754 @Override onBootPhase(int phase)2755 public void onBootPhase(int phase) { 2756 super.onBootPhase(phase); 2757 } 2758 } 2759 } 2760