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.FileUtils; 28 import android.os.Handler; 29 import android.os.HandlerThread; 30 import android.os.IBinder; 31 import android.os.IProfilingResultCallback; 32 import android.os.IProfilingService; 33 import android.os.ParcelFileDescriptor; 34 import android.os.ProfilingManager; 35 import android.os.ProfilingResult; 36 import android.os.RemoteException; 37 import android.provider.DeviceConfig; 38 import android.text.TextUtils; 39 import android.util.ArrayMap; 40 import android.util.Log; 41 import android.util.SparseArray; 42 43 import com.android.internal.annotations.GuardedBy; 44 import com.android.internal.annotations.VisibleForTesting; 45 import com.android.server.SystemService; 46 47 import java.io.File; 48 import java.io.FileInputStream; 49 import java.io.FileOutputStream; 50 import java.io.FilenameFilter; 51 import java.io.IOException; 52 import java.nio.file.Files; 53 import java.nio.file.Path; 54 import java.util.ArrayList; 55 import java.util.List; 56 import java.util.Locale; 57 import java.util.UUID; 58 import java.util.concurrent.TimeUnit; 59 60 public class ProfilingService extends IProfilingService.Stub { 61 private static final String TAG = ProfilingService.class.getSimpleName(); 62 private static final boolean DEBUG = false; 63 64 private static final String TEMP_TRACE_PATH = "/data/misc/perfetto-traces/profiling/"; 65 private static final String OUTPUT_FILE_RELATIVE_PATH = "/profiling/"; 66 private static final String OUTPUT_FILE_SECTION_SEPARATOR = "_"; 67 private static final String OUTPUT_FILE_PREFIX = "profile"; 68 // Keep in sync with {@link ProfilingFrameworkTests}. 69 private static final String OUTPUT_FILE_JAVA_HEAP_DUMP_SUFFIX = ".perfetto-java-heap-dump"; 70 private static final String OUTPUT_FILE_HEAP_PROFILE_SUFFIX = ".perfetto-heap-profile"; 71 private static final String OUTPUT_FILE_STACK_SAMPLING_SUFFIX = ".perfetto-stack-sample"; 72 private static final String OUTPUT_FILE_TRACE_SUFFIX = ".perfetto-trace"; 73 private static final String OUTPUT_FILE_UNREDACTED_TRACE_SUFFIX = ".perfetto-trace-unredacted"; 74 75 private static final int TAG_MAX_CHARS_FOR_FILENAME = 20; 76 77 private static final int PERFETTO_DESTROY_DEFAULT_TIMEOUT_MS = 10 * 1000; 78 79 private static final int DEFAULT_MAX_RESULT_REDELIVERY_COUNT = 3; 80 81 private static final int REDACTION_DEFAULT_MAX_RUNTIME_ALLOTTED_MS = 20 * 1000; 82 83 private static final int REDACTION_DEFAULT_CHECK_FREQUENCY_MS = 2 * 1000; 84 85 // The cadence at which the profiling process will be checked after the initial delay 86 // has elapsed. 87 private static final int PROFILING_DEFAULT_RECHECK_DELAY_MS = 5 * 1000; 88 89 private static final int CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_DEFAULT_MS = 24 * 60 * 60 * 1000; 90 private static final int CLEAR_TEMPORARY_DIRECTORY_BOOT_DELAY_DEFAULT_MS = 5 * 60 * 1000; 91 92 // The longest amount of time that we will retain a queued result and continue retrying to 93 // deliver it. After this amount of time the result will be discarded. 94 @VisibleForTesting 95 public static final int QUEUED_RESULT_MAX_RETAINED_DURATION_MS = 7 * 24 * 60 * 60 * 1000; 96 97 private final Context mContext; 98 private final Object mLock = new Object(); 99 private final HandlerThread mHandlerThread = new HandlerThread("ProfilingService"); 100 101 @VisibleForTesting public RateLimiter mRateLimiter = null; 102 103 // Timeout for Perfetto process to successfully stop after we try to stop it. 104 private int mPerfettoDestroyTimeoutMs; 105 private int mMaxResultRedeliveryCount; 106 private int mProfilingRecheckDelayMs; 107 108 @GuardedBy("mLock") 109 private long mLastClearTemporaryDirectoryTimeMs = 0; 110 private int mClearTemporaryDirectoryFrequencyMs; 111 private final int mClearTemporaryDirectoryBootDelayMs; 112 113 private int mRedactionCheckFrequencyMs; 114 private int mRedactionMaxRuntimeAllottedMs; 115 116 private Handler mHandler; 117 118 private Calendar mCalendar = null; 119 private SimpleDateFormat mDateFormat = null; 120 121 // uid indexed collection of lists of callbacks for results. 122 @VisibleForTesting 123 public SparseArray<List<IProfilingResultCallback>> mResultCallbacks = new SparseArray<>(); 124 125 // Request UUID key indexed storage of active tracing sessions. Currently only 1 active session 126 // is supported at a time, but this will be used in future to support multiple. 127 @VisibleForTesting 128 public ArrayMap<String, TracingSession> mTracingSessions = new ArrayMap<>(); 129 130 // uid indexed storage of completed tracing sessions that have not yet successfully handled the 131 // result. 132 @VisibleForTesting 133 public SparseArray<List<TracingSession>> mQueuedTracingResults = new SparseArray<>(); 134 135 /** To be disabled for testing only. */ 136 @GuardedBy("mLock") 137 private boolean mKeepUnredactedTrace = false; 138 139 @VisibleForTesting ProfilingService(Context context)140 public ProfilingService(Context context) { 141 mContext = context; 142 143 mPerfettoDestroyTimeoutMs = DeviceConfigHelper.getInt( 144 DeviceConfigHelper.PERFETTO_DESTROY_TIMEOUT_MS, 145 PERFETTO_DESTROY_DEFAULT_TIMEOUT_MS); 146 147 mMaxResultRedeliveryCount = DeviceConfigHelper.getInt( 148 DeviceConfigHelper.MAX_RESULT_REDELIVERY_COUNT, 149 DEFAULT_MAX_RESULT_REDELIVERY_COUNT); 150 151 mProfilingRecheckDelayMs = DeviceConfigHelper.getInt( 152 DeviceConfigHelper.PROFILING_RECHECK_DELAY_MS, 153 PROFILING_DEFAULT_RECHECK_DELAY_MS); 154 155 mClearTemporaryDirectoryFrequencyMs = DeviceConfigHelper.getInt( 156 DeviceConfigHelper.CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_MS, 157 CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_DEFAULT_MS); 158 159 mClearTemporaryDirectoryBootDelayMs = DeviceConfigHelper.getInt( 160 DeviceConfigHelper.CLEAR_TEMPORARY_DIRECTORY_BOOT_DELAY_MS, 161 CLEAR_TEMPORARY_DIRECTORY_BOOT_DELAY_DEFAULT_MS); 162 163 mRedactionCheckFrequencyMs = DeviceConfigHelper.getInt( 164 DeviceConfigHelper.REDACTION_CHECK_FREQUENCY_MS, 165 REDACTION_DEFAULT_CHECK_FREQUENCY_MS); 166 167 mRedactionMaxRuntimeAllottedMs = DeviceConfigHelper.getInt( 168 DeviceConfigHelper.REDACTION_MAX_RUNTIME_ALLOTTED_MS, 169 REDACTION_DEFAULT_MAX_RUNTIME_ALLOTTED_MS); 170 171 172 mHandlerThread.start(); 173 174 // Get initial value for whether unredacted trace should be retained. 175 // This is used for (automated and manual) testing only. 176 synchronized (mLock) { 177 mKeepUnredactedTrace = DeviceConfigHelper.getTestBoolean( 178 DeviceConfigHelper.DISABLE_DELETE_UNREDACTED_TRACE, false); 179 } 180 // Now subscribe to updates on test config. 181 DeviceConfig.addOnPropertiesChangedListener(DeviceConfigHelper.NAMESPACE_TESTING, 182 mContext.getMainExecutor(), new DeviceConfig.OnPropertiesChangedListener() { 183 @Override 184 public void onPropertiesChanged(@NonNull DeviceConfig.Properties properties) { 185 synchronized (mLock) { 186 mKeepUnredactedTrace = properties.getBoolean( 187 DeviceConfigHelper.DISABLE_DELETE_UNREDACTED_TRACE, false); 188 getRateLimiter().maybeUpdateRateLimiterDisabled(properties); 189 } 190 } 191 }); 192 193 // Subscribe to updates on the main config. 194 DeviceConfig.addOnPropertiesChangedListener(DeviceConfigHelper.NAMESPACE, 195 mContext.getMainExecutor(), new DeviceConfig.OnPropertiesChangedListener() { 196 @Override 197 public void onPropertiesChanged(@NonNull DeviceConfig.Properties properties) { 198 synchronized (mLock) { 199 getRateLimiter().maybeUpdateConfigs(properties); 200 Configs.maybeUpdateConfigs(properties); 201 202 mPerfettoDestroyTimeoutMs = properties.getInt( 203 DeviceConfigHelper.PERFETTO_DESTROY_TIMEOUT_MS, 204 mPerfettoDestroyTimeoutMs); 205 206 mMaxResultRedeliveryCount = properties.getInt( 207 DeviceConfigHelper.MAX_RESULT_REDELIVERY_COUNT, 208 mMaxResultRedeliveryCount); 209 210 mProfilingRecheckDelayMs = properties.getInt( 211 DeviceConfigHelper.PROFILING_RECHECK_DELAY_MS, 212 mProfilingRecheckDelayMs); 213 214 mClearTemporaryDirectoryFrequencyMs = properties.getInt( 215 DeviceConfigHelper.CLEAR_TEMPORARY_DIRECTORY_FREQUENCY_MS, 216 mClearTemporaryDirectoryFrequencyMs); 217 218 // No need to handle updates for 219 // {@link mClearTemporaryDirectoryBootDelayMs} as it's only used on 220 // initialization of this class so by the time this occurs it will never 221 // be used again. 222 223 mRedactionCheckFrequencyMs = properties.getInt( 224 DeviceConfigHelper.REDACTION_CHECK_FREQUENCY_MS, 225 mRedactionCheckFrequencyMs); 226 227 mRedactionMaxRuntimeAllottedMs = properties.getInt( 228 DeviceConfigHelper.REDACTION_MAX_RUNTIME_ALLOTTED_MS, 229 mRedactionMaxRuntimeAllottedMs); 230 } 231 } 232 }); 233 234 // Schedule initial storage cleanup after delay so as not to increase non-critical work 235 // during boot. 236 getHandler().postDelayed(new Runnable() { 237 @Override 238 public void run() { 239 maybeCleanupTemporaryDirectory(); 240 } 241 }, mClearTemporaryDirectoryBootDelayMs); 242 } 243 244 /** Perform a temporary directory cleanup if it has been long enough to warrant one. */ maybeCleanupTemporaryDirectory()245 private void maybeCleanupTemporaryDirectory() { 246 synchronized (mLock) { 247 if (mLastClearTemporaryDirectoryTimeMs + mClearTemporaryDirectoryFrequencyMs 248 < System.currentTimeMillis()) { 249 cleanupTemporaryDirectoryLocked(TEMP_TRACE_PATH); 250 } 251 } 252 } 253 254 255 /** Cleanup untracked data stored in provided directory. */ 256 @GuardedBy("mLock") 257 @VisibleForTesting cleanupTemporaryDirectoryLocked(String temporaryDirectoryPath)258 public void cleanupTemporaryDirectoryLocked(String temporaryDirectoryPath) { 259 // Obtain a list of all currently tracked files and create a filter with it. Filter is set 260 // to null if the list is empty as that will efficiently accept all files. 261 final List<String> trackedFilenames = getTrackedFilenames(); 262 FilenameFilter filenameFilter = trackedFilenames.isEmpty() ? null : new FilenameFilter() { 263 @Override 264 public boolean accept(File dir, String name) { 265 // We only want to accept files which are not in the tracked files list. 266 return !trackedFilenames.contains(name); 267 } 268 }; 269 270 // Now obtain a list of files in the provided directory that are not tracked. 271 File directory = new File(temporaryDirectoryPath); 272 File[] files = null; 273 try { 274 files = directory.listFiles(filenameFilter); 275 } catch (SecurityException e) { 276 // Couldn't get a list of files, can't cleanup anything. 277 if (DEBUG) { 278 Log.d(TAG, "Failed to get file list from temporary directory. Cleanup aborted.", e); 279 } 280 return; 281 } 282 283 if (files == null) { 284 // The path doesn't exist or an I/O error occurred. 285 if (DEBUG) { 286 Log.d(TAG, "Temporary directory doesn't exist or i/o error occurred. " 287 + "Cleanup aborted."); 288 } 289 return; 290 } 291 292 // Set time here as we'll either return due to no files or attempt to delete files, after 293 // either of which we should wait before checking again. 294 mLastClearTemporaryDirectoryTimeMs = System.currentTimeMillis(); 295 296 if (files.length == 0) { 297 // No files, nothing to cleanup. 298 if (DEBUG) Log.d(TAG, "No files in temporary directory to cleanup."); 299 return; 300 } 301 302 // Iterate through and delete them. 303 for (int i = 0; i < files.length; i++) { 304 try { 305 files[i].delete(); 306 } catch (SecurityException e) { 307 // Exception deleting file, keep trying for the others. 308 if (DEBUG) Log.d(TAG, "Exception deleting file from temp directory.", e); 309 } 310 } 311 } 312 313 /** 314 * Return a list of all filenames that are currently tracked in either the in progress 315 * collections or the queued results, including both redacted and unredacted. 316 */ getTrackedFilenames()317 private List<String> getTrackedFilenames() { 318 List<String> filenames = new ArrayList<String>(); 319 320 // If active sessions is not empty, iterate through and add the filenames from each. 321 if (!mTracingSessions.isEmpty()) { 322 for (int i = 0; i < mTracingSessions.size(); i++) { 323 TracingSession session = mTracingSessions.valueAt(i); 324 String filename = session.getFileName(); 325 if (filename != null) { 326 filenames.add(filename); 327 } 328 String redactedFilename = session.getRedactedFileName(); 329 if (redactedFilename != null) { 330 filenames.add(redactedFilename); 331 } 332 } 333 } 334 335 // If queued sessions is not empty, iterate through and add the filenames from each. 336 if (mQueuedTracingResults.size() != 0) { 337 for (int i = 0; i < mQueuedTracingResults.size(); i++) { 338 List<TracingSession> perUidSessions = mQueuedTracingResults.valueAt(i); 339 if (!perUidSessions.isEmpty()) { 340 for (int j = 0; j < perUidSessions.size(); j++) { 341 TracingSession session = perUidSessions.get(j); 342 String filename = session.getFileName(); 343 if (filename != null) { 344 filenames.add(filename); 345 } 346 String redactedFilename = session.getRedactedFileName(); 347 if (redactedFilename != null) { 348 filenames.add(redactedFilename); 349 } 350 } 351 } 352 } 353 } 354 355 return filenames; 356 } 357 358 /** 359 * This method validates the request, arguments, whether the app is allowed to profile now, 360 * and if so, starts the profiling. 361 */ requestProfiling(int profilingType, Bundle params, String filePath, String tag, long keyMostSigBits, long keyLeastSigBits, String packageName)362 public void requestProfiling(int profilingType, Bundle params, String filePath, String tag, 363 long keyMostSigBits, long keyLeastSigBits, String packageName) { 364 int uid = Binder.getCallingUid(); 365 366 if (profilingType != ProfilingManager.PROFILING_TYPE_JAVA_HEAP_DUMP 367 && profilingType != ProfilingManager.PROFILING_TYPE_HEAP_PROFILE 368 && profilingType != ProfilingManager.PROFILING_TYPE_STACK_SAMPLING 369 && profilingType != ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) { 370 if (DEBUG) Log.d(TAG, "Invalid request profiling type: " + profilingType); 371 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 372 ProfilingResult.ERROR_FAILED_INVALID_REQUEST, null, tag, 373 "Invalid request profiling type"); 374 return; 375 } 376 377 cleanupActiveTracingSessions(); 378 379 // Check if we're running another trace so we don't run multiple at once. 380 try { 381 if (areAnyTracesRunning()) { 382 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 383 ProfilingResult.ERROR_FAILED_PROFILING_IN_PROGRESS, null, tag, null); 384 return; 385 } 386 } catch (RuntimeException e) { 387 if (DEBUG) Log.d(TAG, "Error communicating with perfetto", e); 388 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 389 ProfilingResult.ERROR_UNKNOWN, null, tag, "Error communicating with perfetto"); 390 return; 391 } 392 393 if (packageName == null) { 394 // This shouldn't happen as it should be checked on the app side. 395 if (DEBUG) Log.d(TAG, "PackageName is null"); 396 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 397 ProfilingResult.ERROR_UNKNOWN, null, tag, "Couldn't determine package name"); 398 return; 399 } 400 401 String[] uidPackages = mContext.getPackageManager().getPackagesForUid(uid); 402 if (uidPackages == null || uidPackages.length == 0) { 403 // Failed to get uids for this package, can't validate package name. 404 if (DEBUG) Log.d(TAG, "Failed to resolve package name"); 405 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 406 ProfilingResult.ERROR_UNKNOWN, null, tag, "Couldn't determine package name"); 407 return; 408 } 409 410 boolean packageNameInUidList = false; 411 for (int i = 0; i < uidPackages.length; i++) { 412 if (packageName.equals(uidPackages[i])) { 413 packageNameInUidList = true; 414 break; 415 } 416 } 417 if (!packageNameInUidList) { 418 // Package name is not associated with calling uid, reject request. 419 if (DEBUG) Log.d(TAG, "Package name not associated with calling uid"); 420 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 421 ProfilingResult.ERROR_FAILED_INVALID_REQUEST, null, tag, 422 "Package name not associated with calling uid."); 423 return; 424 } 425 426 // Check with rate limiter if this request is allowed. 427 final int status = getRateLimiter().isProfilingRequestAllowed(Binder.getCallingUid(), 428 profilingType, params); 429 if (DEBUG) Log.d(TAG, "Rate limiter status: " + status); 430 if (status == RateLimiter.RATE_LIMIT_RESULT_ALLOWED) { 431 // Rate limiter approved, try to start the request. 432 try { 433 TracingSession session = new TracingSession(profilingType, params, filePath, uid, 434 packageName, tag, keyMostSigBits, keyLeastSigBits); 435 startProfiling(session); 436 } catch (IllegalArgumentException e) { 437 // This should not happen, it should have been caught when checking rate limiter. 438 // Issue with the request. Apps fault. 439 if (DEBUG) { 440 Log.d(TAG, 441 "Invalid request at config generation. This should not have happened.", 442 e); 443 } 444 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 445 ProfilingResult.ERROR_FAILED_INVALID_REQUEST, null, tag, e.getMessage()); 446 return; 447 } catch (RuntimeException e) { 448 // Perfetto error. Systems fault. 449 if (DEBUG) Log.d(TAG, "Perfetto error", e); 450 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 451 ProfilingResult.ERROR_UNKNOWN, null, tag, "Perfetto error"); 452 return; 453 } 454 } else { 455 // Rate limiter denied, notify caller. 456 if (DEBUG) Log.d(TAG, "Request denied with status: " + status); 457 processResultCallback(uid, keyMostSigBits, keyLeastSigBits, 458 RateLimiter.statusToResult(status), null, tag, null); 459 } 460 } 461 462 /** Call from application to register a callback object. */ registerResultsCallback(boolean isGeneralCallback, IProfilingResultCallback callback)463 public void registerResultsCallback(boolean isGeneralCallback, 464 IProfilingResultCallback callback) { 465 maybeCleanupResultsCallbacks(); 466 467 int callingUid = Binder.getCallingUid(); 468 List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(callingUid); 469 if (perUidCallbacks == null) { 470 perUidCallbacks = new ArrayList<IProfilingResultCallback>(); 471 mResultCallbacks.put(callingUid, perUidCallbacks); 472 } 473 perUidCallbacks.add(callback); 474 475 ProfilingDeathRecipient deathRecipient = new ProfilingDeathRecipient(callingUid); 476 try { 477 callback.asBinder().linkToDeath(deathRecipient, 0); 478 } catch (RemoteException e) { 479 // Failed to link death recipient. Ignore. 480 if (DEBUG) Log.d(TAG, "Exception linking death recipient", e); 481 } 482 483 // Only handle queued results when a new general listener has been added. 484 if (isGeneralCallback) { 485 handleQueuedResults(callingUid); 486 } 487 } 488 489 /** 490 * Iterate through and delete any callbacks for which binder is not alive. 491 * 492 * Each binder object has a registered linkToDeath which also handles removal. This mechanism 493 * serves as a backup to guarantee that the list stays in check. 494 */ maybeCleanupResultsCallbacks()495 private void maybeCleanupResultsCallbacks() { 496 // Create a temporary list to hold callbacks to be removed. 497 ArrayList<IProfilingResultCallback> callbacksToRemove = 498 new ArrayList<IProfilingResultCallback>(); 499 500 // Iterate through the results callback, each iteration is for a uid which has registered 501 // callbacks. 502 for (int i = 0; i < mResultCallbacks.size(); i++) { 503 // Ensure the temporary list is empty 504 callbacksToRemove.clear(); 505 506 // Grab the current list of callbacks. 507 List<IProfilingResultCallback> callbacks = mResultCallbacks.valueAt(i); 508 509 if (callbacks != null && !callbacks.isEmpty()) { 510 // Now iterate through each of the callbacks for this uid. 511 for (int j = 0; j < callbacks.size(); j++) { 512 IProfilingResultCallback callback = callbacks.get(j); 513 // If the callback is no longer alive, add it to the list for removal. 514 if (callback == null || !callback.asBinder().isBinderAlive()) { 515 callbacksToRemove.add(callback); 516 } 517 } 518 519 // Now remove all the callbacks that were added to the list for removal. 520 callbacks.removeAll(callbacksToRemove); 521 } 522 } 523 } 524 525 /** 526 * Call from application to notify that a new global listener was added and can be accessed 527 * through the existing callback object. 528 */ generalListenerAdded()529 public void generalListenerAdded() { 530 handleQueuedResults(Binder.getCallingUid()); 531 } 532 requestCancel(long keyMostSigBits, long keyLeastSigBits)533 public void requestCancel(long keyMostSigBits, long keyLeastSigBits) { 534 String key = (new UUID(keyMostSigBits, keyLeastSigBits)).toString(); 535 if (!isTraceRunning(key)) { 536 // No trace running, nothing to cancel. 537 if (DEBUG) { 538 Log.d(TAG, "Exited requestCancel without stopping trace key:" + key 539 + " due to no trace running."); 540 } 541 return; 542 } 543 stopProfiling(key); 544 } 545 546 /** 547 * Method called by manager, after creating a file from within application context, to send a 548 * file descriptor for service to write the result of the profiling session to. 549 * 550 * Note: only expected to be called in response to a generateFile request sent to manager. 551 */ receiveFileDescriptor(ParcelFileDescriptor fileDescriptor, long keyMostSigBits, long keyLeastSigBits)552 public void receiveFileDescriptor(ParcelFileDescriptor fileDescriptor, long keyMostSigBits, 553 long keyLeastSigBits) { 554 List<TracingSession> sessions = mQueuedTracingResults.get(Binder.getCallingUid()); 555 if (sessions == null) { 556 // No sessions for this uid, so no profiling result to write to this file descriptor. 557 // Attempt to cleanup. 558 finishReceiveFileDescriptor(null, fileDescriptor, null, null, false); 559 return; 560 } 561 562 TracingSession session = null; 563 // Iterate through and try to find the session this file is associated with using the 564 // key values. Key values were provided from the session to the generate file call that 565 // triggered this. 566 String key = (new UUID(keyMostSigBits, keyLeastSigBits)).toString(); 567 for (int i = 0; i < sessions.size(); i++) { 568 TracingSession tempSession = sessions.get(i); 569 if (tempSession.getKey().equals(key)) { 570 session = tempSession; 571 break; 572 } 573 } 574 if (session == null) { 575 // No session for the provided key, nothing to do with this file descriptor. Attempt 576 // to cleanup. 577 finishReceiveFileDescriptor(session, fileDescriptor, null, null, false); 578 return; 579 } 580 581 // At this point we've identified the session that has sent us this file descriptor. 582 // Now, we'll create a temporary file pointing to the profiling output for that session. 583 // If that file looks good, we'll copy it to the app's local file descriptor. 584 File tempResultFile = new File(TEMP_TRACE_PATH 585 + (session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE 586 ? session.getRedactedFileName() : session.getFileName())); 587 FileInputStream tempPerfettoFileInStream = null; 588 FileOutputStream appFileOutStream = null; 589 590 try { 591 if (!tempResultFile.exists() || tempResultFile.length() == 0L) { 592 // The profiling process output file does not exist or is empty, nothing to copy. 593 if (DEBUG) { 594 Log.d(TAG, "Temporary profiling output file is missing or empty, nothing to" 595 + " copy."); 596 } 597 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 598 appFileOutStream, false); 599 return; 600 } 601 } catch (SecurityException e) { 602 // If we hit a security exception checking file exists or size then we won't be able to 603 // copy it, attempt to cleanup and return. 604 if (DEBUG) { 605 Log.d(TAG, "Exception checking if temporary file exists and is non-empty", e); 606 } 607 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 608 appFileOutStream, false); 609 return; 610 } 611 612 // Only copy the file if we haven't previously. 613 if (session.getState().getValue() < TracingSession.TracingState.COPIED_FILE.getValue()) { 614 // Setup file streams. 615 try { 616 tempPerfettoFileInStream = new FileInputStream(tempResultFile); 617 } catch (IOException e) { 618 // IO Exception opening temp perfetto file. No result. 619 if (DEBUG) Log.d(TAG, "Exception opening temp perfetto file.", e); 620 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 621 appFileOutStream, false); 622 return; 623 } 624 625 // Obtain a file descriptor for the result file in app storage from 626 // {@link ProfilingManager} 627 if (fileDescriptor != null) { 628 appFileOutStream = new FileOutputStream(fileDescriptor.getFileDescriptor()); 629 } 630 631 if (appFileOutStream == null) { 632 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 633 appFileOutStream, false); 634 return; 635 } 636 637 // Now copy the file over. 638 try { 639 FileUtils.copy(tempPerfettoFileInStream, appFileOutStream); 640 session.setState(TracingSession.TracingState.COPIED_FILE); 641 } catch (IOException e) { 642 // Exception writing to local app file. Attempt to delete the bad copy. 643 deleteBadCopiedFile(session); 644 if (DEBUG) Log.d(TAG, "Exception writing to local app file.", e); 645 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 646 appFileOutStream, false); 647 return; 648 } 649 } 650 651 finishReceiveFileDescriptor(session, fileDescriptor, tempPerfettoFileInStream, 652 appFileOutStream, true); 653 } 654 finishReceiveFileDescriptor(TracingSession session, ParcelFileDescriptor fileDescriptor, FileInputStream tempPerfettoFileInStream, FileOutputStream appFileOutStream, boolean succeeded)655 private void finishReceiveFileDescriptor(TracingSession session, 656 ParcelFileDescriptor fileDescriptor, FileInputStream tempPerfettoFileInStream, 657 FileOutputStream appFileOutStream, boolean succeeded) { 658 // Cleanup. 659 if (tempPerfettoFileInStream != null) { 660 try { 661 tempPerfettoFileInStream.close(); 662 } catch (IOException e) { 663 if (DEBUG) Log.d(TAG, "Failed to close temp perfetto input stream.", e); 664 } 665 } 666 if (fileDescriptor != null) { 667 try { 668 fileDescriptor.close(); 669 } catch (IOException e) { 670 if (DEBUG) Log.d(TAG, "Failed to close app file output file FileDescriptor.", e); 671 } 672 } 673 if (appFileOutStream != null) { 674 try { 675 appFileOutStream.close(); 676 } catch (IOException e) { 677 if (DEBUG) Log.d(TAG, "Failed to close app file output file stream.", e); 678 } 679 } 680 681 if (session != null) { 682 finishProcessingResult(session, succeeded); 683 } 684 } 685 processResultCallback(TracingSession session, int status, @Nullable String error)686 private void processResultCallback(TracingSession session, int status, @Nullable String error) { 687 processResultCallback(session.getUid(), session.getKeyMostSigBits(), 688 session.getKeyLeastSigBits(), status, 689 session.getDestinationFileName(OUTPUT_FILE_RELATIVE_PATH), 690 session.getTag(), error); 691 } 692 693 /** 694 * An app can register multiple callbacks between this service and {@link ProfilingManager}, one 695 * per context that the app created a manager instance with. As we do not know on this service 696 * side which callbacks need to be triggered with this result, trigger all of them and let them 697 * decide whether to finish delivering it. 698 */ processResultCallback(int uid, long keyMostSigBits, long keyLeastSigBits, int status, @Nullable String filePath, @Nullable String tag, @Nullable String error)699 private void processResultCallback(int uid, long keyMostSigBits, long keyLeastSigBits, 700 int status, @Nullable String filePath, @Nullable String tag, @Nullable String error) { 701 List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(uid); 702 if (perUidCallbacks == null || perUidCallbacks.isEmpty()) { 703 // No callbacks, nowhere to notify with result or failure. 704 if (DEBUG) Log.d(TAG, "No callback to ProfilingManager, callback dropped."); 705 return; 706 } 707 708 for (int i = 0; i < perUidCallbacks.size(); i++) { 709 try { 710 perUidCallbacks.get(i).sendResult(filePath, keyMostSigBits, keyLeastSigBits, status, 711 tag, error); 712 } catch (RemoteException e) { 713 // Failed to send result. Ignore. 714 if (DEBUG) Log.d(TAG, "Exception processing result callback", e); 715 } 716 } 717 } 718 startProfiling(final TracingSession session)719 private void startProfiling(final TracingSession session) 720 throws RuntimeException { 721 // Parse config and post processing delay out of request first, if we can't get these 722 // we can't start the trace. 723 int postProcessingInitialDelayMs; 724 byte[] config; 725 String suffix; 726 String tag; 727 try { 728 postProcessingInitialDelayMs = session.getPostProcessingScheduleDelayMs(); 729 config = session.getConfigBytes(); 730 suffix = getFileSuffixForRequest(session.getProfilingType()); 731 732 // Create a version of tag that is non null, containing only valid filename chars, 733 // and shortened to class defined max size. 734 tag = session.getTag() == null 735 ? "" : removeInvalidFilenameChars(session.getTag()); 736 if (tag.length() > TAG_MAX_CHARS_FOR_FILENAME) { 737 tag = tag.substring(0, TAG_MAX_CHARS_FOR_FILENAME); 738 } 739 } catch (IllegalArgumentException e) { 740 // Request couldn't be processed. This shouldn't happen. 741 if (DEBUG) Log.d(TAG, "Request couldn't be processed", e); 742 processResultCallback(session, ProfilingResult.ERROR_FAILED_INVALID_REQUEST, 743 e.getMessage()); 744 return; 745 746 } 747 748 String baseFileName = OUTPUT_FILE_PREFIX 749 + (tag.isEmpty() ? "" : OUTPUT_FILE_SECTION_SEPARATOR + tag) 750 + OUTPUT_FILE_SECTION_SEPARATOR + getFormattedDate(); 751 752 // Only trace files will go through the redaction process, set the name here for the file 753 // that will be created later when results are processed. 754 if (session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) { 755 session.setRedactedFileName(baseFileName + OUTPUT_FILE_TRACE_SUFFIX); 756 } 757 758 session.setFileName(baseFileName + suffix); 759 760 try { 761 ProcessBuilder pb = new ProcessBuilder("/system/bin/perfetto", "-o", 762 TEMP_TRACE_PATH + session.getFileName(), "-c", "-"); 763 Process activeTrace = pb.start(); 764 activeTrace.getOutputStream().write(config); 765 activeTrace.getOutputStream().close(); 766 // If we made it this far the trace is running, save the session. 767 session.setActiveTrace(activeTrace); 768 session.setProfilingStartTimeMs(System.currentTimeMillis()); 769 mTracingSessions.put(session.getKey(), session); 770 } catch (Exception e) { 771 // Catch all exceptions related to starting process as they'll all be handled similarly. 772 if (DEBUG) Log.d(TAG, "Trace couldn't be started", e); 773 processResultCallback(session, ProfilingResult.ERROR_FAILED_EXECUTING, null); 774 return; 775 } 776 777 session.setState(TracingSession.TracingState.PROFILING_STARTED); 778 779 // Create post process runnable, store it, and schedule it. 780 session.setProcessResultRunnable(new Runnable() { 781 @Override 782 public void run() { 783 // Check if the profiling process is complete or reschedule the check. 784 checkProfilingCompleteRescheduleIfNeeded(session); 785 } 786 }); 787 getHandler().postDelayed(session.getProcessResultRunnable(), postProcessingInitialDelayMs); 788 } 789 790 /** 791 This method will check if the profiling subprocess is still alive. If it's still alive and 792 there is still time permitted to run, another check will be scheduled. If the process is 793 still alive but max allotted processing time has been exceeded, the profiling process will 794 be stopped and results processed and returned to client. If the profiling process is 795 complete results will be processed and returned to the client. 796 */ checkProfilingCompleteRescheduleIfNeeded(TracingSession session)797 private void checkProfilingCompleteRescheduleIfNeeded(TracingSession session) { 798 799 long processingTimeRemaining = session.getMaxProfilingTimeAllowedMs() 800 - (System.currentTimeMillis() - session.getProfilingStartTimeMs()); 801 802 if (session.getActiveTrace().isAlive() 803 && processingTimeRemaining >= 0) { 804 // still running and under max allotted processing time, reschedule the check. 805 getHandler().postDelayed(session.getProcessResultRunnable(), 806 Math.min(mProfilingRecheckDelayMs, processingTimeRemaining)); 807 } else if (session.getActiveTrace().isAlive() 808 && processingTimeRemaining < 0) { 809 // still running but exceeded max allotted processing time, stop profiling and deliver 810 // what results are available. 811 stopProfiling(session.getKey()); 812 } else { 813 // complete, process results and deliver. 814 session.setProcessResultRunnable(null); 815 processResult(session); 816 } 817 } 818 819 /** Stop any active profiling sessions belonging to the provided uid. */ stopAllProfilingForUid(int uid)820 private void stopAllProfilingForUid(int uid) { 821 if (mTracingSessions.isEmpty()) { 822 // If there are no active traces, then there are none for this uid. 823 return; 824 } 825 826 // Iterate through active sessions and stop profiling if they belong to the provided uid. 827 // Note: Currently, this will only ever have 1 session. 828 for (int i = 0; i < mTracingSessions.size(); i++) { 829 TracingSession session = mTracingSessions.valueAt(i); 830 if (session.getUid() == uid) { 831 stopProfiling(session); 832 } 833 } 834 } 835 stopProfiling(String key)836 private void stopProfiling(String key) throws RuntimeException { 837 TracingSession session = mTracingSessions.get(key); 838 stopProfiling(session); 839 } 840 stopProfiling(TracingSession session)841 private void stopProfiling(TracingSession session) throws RuntimeException { 842 if (session == null || session.getActiveTrace() == null) { 843 if (DEBUG) Log.d(TAG, "No active trace, nothing to stop."); 844 return; 845 } 846 847 if (session.getProcessResultRunnable() == null) { 848 if (DEBUG) { 849 Log.d(TAG, 850 "No runnable, it either stopped already or is in the process of stopping."); 851 } 852 return; 853 } 854 855 // Remove the post processing runnable set with the default timeout. After stopping use the 856 // same runnable to process immediately. 857 getHandler().removeCallbacks(session.getProcessResultRunnable()); 858 859 // End the tracing session. 860 session.getActiveTrace().destroyForcibly(); 861 try { 862 if (!session.getActiveTrace().waitFor(mPerfettoDestroyTimeoutMs, 863 TimeUnit.MILLISECONDS)) { 864 if (DEBUG) Log.d(TAG, "Stopping of running trace process timed out."); 865 throw new RuntimeException("Stopping of running trace process timed out."); 866 } 867 } catch (InterruptedException e) { 868 throw new RuntimeException(e); 869 } 870 871 // If we made it here the result is ready, now run the post processing runnable. 872 getHandler().post(session.getProcessResultRunnable()); 873 } 874 areAnyTracesRunning()875 public boolean areAnyTracesRunning() throws RuntimeException { 876 for (int i = 0; i < mTracingSessions.size(); i++) { 877 if (isTraceRunning(mTracingSessions.keyAt(i))) { 878 return true; 879 } 880 } 881 return false; 882 } 883 884 /** 885 * Cleanup the data structure of active sessions. Non active sessions are never expected to be 886 * present in {@link mTracingSessions} as they would be moved to {@link mQueuedTracingResults} 887 * when profiling completes. If a session is present but not running, remove it. If a session 888 * has a not alive process, try to stop it. 889 */ cleanupActiveTracingSessions()890 public void cleanupActiveTracingSessions() throws RuntimeException { 891 // Create a temporary list to store the keys of sessions to be stopped. 892 ArrayList<String> sessionsToStop = new ArrayList<String>(); 893 894 // Iterate through in reverse order so we can immediately remove the non running sessions 895 // that don't have to be stopped. 896 for (int i = mTracingSessions.size() - 1; i >= 0; i--) { 897 String key = mTracingSessions.keyAt(i); 898 TracingSession session = mTracingSessions.get(key); 899 900 if (session == null || session.getActiveTrace() == null) { 901 // Profiling isn't running, remove from list. 902 mTracingSessions.removeAt(i); 903 } else if (!session.getActiveTrace().isAlive()) { 904 // Profiling process exists but isn't alive, add to list of sessions to stop. Do not 905 // stop here due to potential unanticipated modification of list being iterated 906 // through. 907 sessionsToStop.add(key); 908 } 909 } 910 911 // If we have any sessions to stop, now is the time. 912 if (!sessionsToStop.isEmpty()) { 913 for (int i = 0; i < sessionsToStop.size(); i++) { 914 stopProfiling(sessionsToStop.get(i)); 915 } 916 } 917 } 918 isTraceRunning(String key)919 public boolean isTraceRunning(String key) throws RuntimeException { 920 TracingSession session = mTracingSessions.get(key); 921 if (session == null || session.getActiveTrace() == null) { 922 // No subprocess, nothing running. 923 if (DEBUG) Log.d(TAG, "No subprocess, nothing running."); 924 return false; 925 } else if (session.getActiveTrace().isAlive()) { 926 // Subprocess exists and is alive. 927 if (DEBUG) Log.d(TAG, "Subprocess exists and is alive, trace is running."); 928 return true; 929 } else { 930 // Subprocess exists but is not alive, nothing running. 931 if (DEBUG) Log.d(TAG, "Subprocess exists but is not alive, nothing running."); 932 return false; 933 } 934 } 935 936 /** 937 * Begin moving result to storage by validating and then sending a request to 938 * {@link ProfilingManager} for a file to write to. File will be returned as a 939 * {@link ParcelFileDescriptor} via {@link sendFileDescriptor}. 940 */ 941 @VisibleForTesting beginMoveFileToAppStorage(TracingSession session)942 public void beginMoveFileToAppStorage(TracingSession session) { 943 if (session.getState() == TracingSession.TracingState.DISCARDED) { 944 // This should not have happened, if the session was discarded why are we trying to 945 // continue processing it? Remove from all data stores just in case. 946 if (DEBUG) { 947 Log.d(TAG, "Attempted beginMoveFileToAppStorage on a session with status discarded" 948 + " or an invalid status."); 949 } 950 mTracingSessions.remove(session.getKey()); 951 cleanupTracingSession(session); 952 return; 953 } 954 955 List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(session.getUid()); 956 if (perUidCallbacks == null || perUidCallbacks.isEmpty()) { 957 // No callback so no way to obtain a file to populate with result. 958 if (DEBUG) Log.d(TAG, "No callback to ProfilingManager, callback dropped."); 959 // TODO: b/333456916 run a cleanup of old results based on a max size and time. 960 return; 961 } 962 963 requestFileForResult(perUidCallbacks, session); 964 } 965 966 /** 967 * Finish processing profiling result by sending the appropriate callback and cleaning up 968 * temporary directory. 969 */ 970 @VisibleForTesting finishProcessingResult(TracingSession session, boolean success)971 public void finishProcessingResult(TracingSession session, boolean success) { 972 if (success) { 973 processResultCallback(session, ProfilingResult.ERROR_NONE, null); 974 cleanupTracingSession(session); 975 } else { 976 // Couldn't move file. File is still in temp directory and will be tried later. 977 if (DEBUG) Log.d(TAG, "Couldn't move file to app storage."); 978 processResultCallback(session, ProfilingResult.ERROR_FAILED_POST_PROCESSING, null); 979 } 980 981 // Clean up temporary directory if it has been long enough to warrant it. 982 maybeCleanupTemporaryDirectory(); 983 } 984 985 /** 986 * Delete a file which failed to copy via ProfilingManager. 987 */ deleteBadCopiedFile(TracingSession session)988 private void deleteBadCopiedFile(TracingSession session) { 989 List<IProfilingResultCallback> perUidCallbacks = mResultCallbacks.get(session.getUid()); 990 for (int i = 0; i < perUidCallbacks.size(); i++) { 991 try { 992 String fileName = 993 session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE 994 ? session.getRedactedFileName() : session.getFileName(); 995 IProfilingResultCallback callback = perUidCallbacks.get(i); 996 if (callback.asBinder().isBinderAlive()) { 997 callback.deleteFile( 998 session.getAppFilePath() + OUTPUT_FILE_RELATIVE_PATH + fileName); 999 // Only need one delete call, return. 1000 return; 1001 } 1002 } catch (RemoteException e) { 1003 // Binder exception deleting file. Continue trying other callbacks for this process. 1004 if (DEBUG) Log.d(TAG, "Binder exception deleting file. Trying next callback", e); 1005 } 1006 } 1007 } 1008 1009 /** 1010 * Request a {@link ParcelFileDescriptor} to a new file in app storage from the first live 1011 * callback for this uid. 1012 * 1013 * The new file is created by {@link ProfilingManager} from within app context. We only need a 1014 * single file, which can be created from any of the contexts belonging to the app that 1015 * requested this profiling, so it does not matter which of the requesting app's callbacks we 1016 * use. 1017 */ 1018 @Nullable requestFileForResult( @onNull List<IProfilingResultCallback> perUidCallbacks, TracingSession session)1019 private void requestFileForResult( 1020 @NonNull List<IProfilingResultCallback> perUidCallbacks, TracingSession session) { 1021 String filePath = session.getAppFilePath() + OUTPUT_FILE_RELATIVE_PATH; 1022 String fileName = session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE 1023 ? session.getRedactedFileName() 1024 : session.getFileName(); 1025 for (int i = 0; i < perUidCallbacks.size(); i++) { 1026 try { 1027 IProfilingResultCallback callback = perUidCallbacks.get(i); 1028 if (callback.asBinder().isBinderAlive()) { 1029 // Great, this one works! Call it and exit if we don't hit an exception. 1030 perUidCallbacks.get(i).generateFile(filePath, fileName, 1031 session.getKeyMostSigBits(), session.getKeyLeastSigBits()); 1032 return; 1033 } 1034 } catch (RemoteException e) { 1035 // Binder exception getting file. Continue trying other callbacks for this process. 1036 if (DEBUG) Log.d(TAG, "Binder exception getting file. Trying next callback", e); 1037 } 1038 } 1039 if (DEBUG) Log.d(TAG, "Failed to obtain file descriptor from callbacks."); 1040 } 1041 1042 1043 // processResult will be called after every profiling type is collected, traces will go 1044 // through a redaction process before being returned to the client. All other profiling types 1045 // can be returned as is. processResult(TracingSession session)1046 private void processResult(TracingSession session) { 1047 // Move this session from active to queued results. 1048 List<TracingSession> queuedResults = mQueuedTracingResults.get(session.getUid()); 1049 if (queuedResults == null) { 1050 queuedResults = new ArrayList<TracingSession>(); 1051 mQueuedTracingResults.put(session.getUid(), queuedResults); 1052 } 1053 queuedResults.add(session); 1054 mTracingSessions.remove(session.getKey()); 1055 1056 session.setState(TracingSession.TracingState.PROFILING_FINISHED); 1057 1058 if (session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) { 1059 handleTraceResult(session); 1060 } else { 1061 beginMoveFileToAppStorage(session); 1062 } 1063 } 1064 1065 /** Handle a trace result by attempting to kick off redaction process. */ 1066 @VisibleForTesting handleTraceResult(TracingSession session)1067 public void handleTraceResult(TracingSession session) { 1068 try { 1069 // We need to create an empty file for the redaction process to write the output into. 1070 File emptyRedactedTraceFile = new File(TEMP_TRACE_PATH 1071 + session.getRedactedFileName()); 1072 emptyRedactedTraceFile.createNewFile(); 1073 } catch (Exception exception) { 1074 if (DEBUG) Log.e(TAG, "Creating empty redacted file failed.", exception); 1075 processResultCallback(session, ProfilingResult.ERROR_FAILED_POST_PROCESSING, null); 1076 return; 1077 } 1078 1079 try { 1080 // Start the redaction process and log the time of start. Redaction has 1081 // mRedactionMaxRuntimeAllottedMs to complete. Redaction status will be checked every 1082 // mRedactionCheckFrequencyMs. 1083 ProcessBuilder redactionProcess = new ProcessBuilder("/system/bin/trace_redactor", 1084 TEMP_TRACE_PATH + session.getFileName(), 1085 TEMP_TRACE_PATH + session.getRedactedFileName(), 1086 session.getPackageName()); 1087 session.setActiveRedaction(redactionProcess.start()); 1088 session.setRedactionStartTimeMs(System.currentTimeMillis()); 1089 } catch (Exception exception) { 1090 if (DEBUG) Log.e(TAG, "Redaction failed to run completely.", exception); 1091 processResultCallback(session, ProfilingResult.ERROR_FAILED_POST_PROCESSING, null); 1092 return; 1093 } 1094 session.setProcessResultRunnable(new Runnable() { 1095 1096 @Override 1097 public void run() { 1098 checkRedactionStatus(session); 1099 } 1100 }); 1101 1102 getHandler().postDelayed(session.getProcessResultRunnable(), 1103 mRedactionCheckFrequencyMs); 1104 } 1105 checkRedactionStatus(TracingSession session)1106 private void checkRedactionStatus(TracingSession session) { 1107 // Check if redaction is complete. 1108 if (!session.getActiveRedaction().isAlive()) { 1109 handleRedactionComplete(session); 1110 session.setProcessResultRunnable(null); 1111 return; 1112 } 1113 1114 // Check if we are over the mRedactionMaxRuntimeAllottedMs threshold. 1115 if ((System.currentTimeMillis() - session.getRedactionStartTimeMs()) 1116 > mRedactionMaxRuntimeAllottedMs) { 1117 if (DEBUG) Log.d(TAG, "Redaction process has timed out"); 1118 1119 session.getActiveRedaction().destroyForcibly(); 1120 session.setProcessResultRunnable(null); 1121 processResultCallback(session, ProfilingResult.ERROR_FAILED_POST_PROCESSING, 1122 null); 1123 1124 return; 1125 } 1126 getHandler().postDelayed(session.getProcessResultRunnable(), 1127 Math.min(mRedactionCheckFrequencyMs, mRedactionMaxRuntimeAllottedMs 1128 - (System.currentTimeMillis() - session.getRedactionStartTimeMs()))); 1129 1130 } 1131 handleRedactionComplete(TracingSession session)1132 private void handleRedactionComplete(TracingSession session) { 1133 int redactionErrorCode = session.getActiveRedaction().exitValue(); 1134 if (redactionErrorCode != 0) { 1135 // Redaction process failed. This failure cannot be recovered. 1136 if (DEBUG) { 1137 Log.d(TAG, String.format("Redaction processed failed with error code: %s", 1138 redactionErrorCode)); 1139 } 1140 cleanupTracingSession(session); 1141 processResultCallback(session, ProfilingResult.ERROR_FAILED_POST_PROCESSING, null); 1142 return; 1143 } 1144 1145 // At this point redaction has completed successfully it is safe to delete the 1146 // unredacted trace file unless {@link mKeepUnredactedTrace} has been enabled. 1147 synchronized (mLock) { 1148 if (mKeepUnredactedTrace) { 1149 Log.i(TAG, "Unredacted trace file retained at: " 1150 + TEMP_TRACE_PATH + session.getFileName()); 1151 } else { 1152 // TODO b/331988161 Delete after file is delivered to app. 1153 maybeDeleteUnredactedTrace(session); 1154 } 1155 } 1156 1157 session.setState(TracingSession.TracingState.REDACTED); 1158 1159 beginMoveFileToAppStorage(session); 1160 } 1161 1162 /** 1163 * Called whenever a new global listener has been added to the specified uid. 1164 * Attempts to process queued results if present. 1165 */ 1166 @VisibleForTesting handleQueuedResults(int uid)1167 public void handleQueuedResults(int uid) { 1168 List<TracingSession> queuedSessions = mQueuedTracingResults.get(uid); 1169 if (queuedSessions == null || queuedSessions.isEmpty()) { 1170 // No queued results for this uid, nothing to handle. Attempt to cleanup the queue for 1171 // all other uids before exiting. 1172 maybeCleanupQueue(); 1173 return; 1174 } 1175 1176 // Triggering the callbacks may result in the object being removed from the class level 1177 // queue list, ensure this remains safe by using a unmodifiable shallow copy of the list. 1178 List<TracingSession> unmodifiableQueuedSessions = List.copyOf(queuedSessions); 1179 for (int i = 0; i < unmodifiableQueuedSessions.size(); i++) { 1180 TracingSession session = unmodifiableQueuedSessions.get(i); 1181 1182 // Check if we already retried too many times and discard the result if we have. 1183 if (session.getRetryCount() >= mMaxResultRedeliveryCount) { 1184 cleanupTracingSession(session, queuedSessions); 1185 continue; 1186 } 1187 session.incrementRetryCount(); 1188 1189 switch (session.getState()) { 1190 case NOT_STARTED: 1191 case PROFILING_STARTED: 1192 // This should never happen as the session should not be in queuedSessions until 1193 // past this state, but run stop and cleanup just in case. 1194 stopProfiling(session); 1195 cleanupTracingSession(session); 1196 break; 1197 case PROFILING_FINISHED: 1198 if (session.getProfilingType() 1199 == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) { 1200 handleTraceResult(session); 1201 } else { 1202 beginMoveFileToAppStorage(session); 1203 } 1204 break; 1205 case REDACTED: 1206 beginMoveFileToAppStorage(session); 1207 break; 1208 case COPIED_FILE: 1209 finishProcessingResult(session, true); 1210 break; 1211 case DISCARDED: 1212 // This should never happen as this state should only occur after cleanup of 1213 // this file. 1214 cleanupTracingSession(session, queuedSessions); 1215 break; 1216 } 1217 } 1218 1219 // Now attempt to cleanup the queue. 1220 maybeCleanupQueue(); 1221 } 1222 1223 /** Run through all queued sessions and clean up the ones that are too old. */ maybeCleanupQueue()1224 private void maybeCleanupQueue() { 1225 List<TracingSession> sessionsToRemove = new ArrayList(); 1226 // Iterate in reverse so we can remove the index if empty. 1227 for (int i = mQueuedTracingResults.size() - 1; i >= 0; i--) { 1228 List<TracingSession> sessions = mQueuedTracingResults.valueAt(i); 1229 if (sessions != null && !sessions.isEmpty()) { 1230 sessionsToRemove.clear(); 1231 for (int j = 0; j < sessions.size(); j++) { 1232 TracingSession session = sessions.get(j); 1233 if (session.getProfilingStartTimeMs() + QUEUED_RESULT_MAX_RETAINED_DURATION_MS 1234 < System.currentTimeMillis()) { 1235 cleanupTracingSession(session); 1236 sessionsToRemove.add(session); 1237 } 1238 } 1239 sessions.removeAll(sessionsToRemove); 1240 if (sessions.isEmpty()) { 1241 mQueuedTracingResults.removeAt(i); 1242 } 1243 } else { 1244 mQueuedTracingResults.removeAt(i); 1245 } 1246 } 1247 } 1248 1249 /** 1250 * Cleanup is intended for when we're done with a queued trace session, whether successful or 1251 * not. 1252 * 1253 * Cleanup will attempt to delete the temporary file(s) and then remove it from the queue. 1254 */ cleanupTracingSession(TracingSession session)1255 private void cleanupTracingSession(TracingSession session) { 1256 List<TracingSession> queuedSessions = mQueuedTracingResults.get(session.getUid()); 1257 cleanupTracingSession(session, queuedSessions); 1258 } 1259 1260 /** 1261 * Cleanup is intended for when we're done with a queued trace session, whether successful or 1262 * not. 1263 * 1264 * Cleanup will attempt to delete the temporary file(s) and then remove it from the queue. 1265 */ cleanupTracingSession(TracingSession session, List<TracingSession> queuedSessions)1266 private void cleanupTracingSession(TracingSession session, 1267 List<TracingSession> queuedSessions) { 1268 // Delete all files 1269 if (session.getProfilingType() == ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE) { 1270 // If type is trace, try to delete the temp file only if {@link mKeepUnredactedTrace} is 1271 // false, and always try to delete redacted file. 1272 maybeDeleteUnredactedTrace(session); 1273 try { 1274 Files.delete(Path.of(TEMP_TRACE_PATH + session.getRedactedFileName())); 1275 } catch (Exception exception) { 1276 if (DEBUG) Log.e(TAG, "Failed to delete file for discarded record.", exception); 1277 } 1278 } else { 1279 // If type is not trace, try to delete the temp file. There is no redacted file. 1280 try { 1281 Files.delete(Path.of(TEMP_TRACE_PATH + session.getFileName())); 1282 } catch (Exception exception) { 1283 if (DEBUG) Log.e(TAG, "Failed to delete file for discarded record.", exception); 1284 } 1285 1286 } 1287 1288 session.setState(TracingSession.TracingState.DISCARDED); 1289 queuedSessions.remove(session); 1290 1291 if (queuedSessions.isEmpty()) { 1292 mQueuedTracingResults.remove(session.getUid()); 1293 } 1294 } 1295 1296 /** 1297 * Attempt to delete unredacted trace unless mKeepUnredactedTrace is enabled. 1298 * 1299 * Note: only to be called for types that support redaction. 1300 */ maybeDeleteUnredactedTrace(TracingSession session)1301 private void maybeDeleteUnredactedTrace(TracingSession session) { 1302 synchronized (mLock) { 1303 if (mKeepUnredactedTrace) { 1304 return; 1305 } 1306 try { 1307 Files.delete(Path.of(TEMP_TRACE_PATH + session.getFileName())); 1308 } catch (Exception exception) { 1309 if (DEBUG) Log.e(TAG, "Failed to delete file.", exception); 1310 } 1311 } 1312 } 1313 getHandler()1314 private Handler getHandler() { 1315 if (mHandler == null) { 1316 mHandler = new Handler(mHandlerThread.getLooper()); 1317 } 1318 return mHandler; 1319 } 1320 getRateLimiter()1321 private RateLimiter getRateLimiter() { 1322 if (mRateLimiter == null) { 1323 mRateLimiter = new RateLimiter(new RateLimiter.HandlerCallback() { 1324 @Override 1325 public Handler obtainHandler() { 1326 return getHandler(); 1327 } 1328 }); 1329 } 1330 return mRateLimiter; 1331 } 1332 getFormattedDate()1333 private String getFormattedDate() { 1334 if (mCalendar == null) { 1335 mCalendar = Calendar.getInstance(TimeZone.getTimeZone("GMT")); 1336 } 1337 if (mDateFormat == null) { 1338 mDateFormat = new SimpleDateFormat("yyyy-MM-dd-HH-mm-ss", Locale.US); 1339 } 1340 mCalendar.setTimeInMillis(System.currentTimeMillis()); 1341 return mDateFormat.format(mCalendar.getTime()); 1342 } 1343 getFileSuffixForRequest(int profilingType)1344 private static String getFileSuffixForRequest(int profilingType) { 1345 switch (profilingType) { 1346 case ProfilingManager.PROFILING_TYPE_JAVA_HEAP_DUMP: 1347 return OUTPUT_FILE_JAVA_HEAP_DUMP_SUFFIX; 1348 case ProfilingManager.PROFILING_TYPE_HEAP_PROFILE: 1349 return OUTPUT_FILE_HEAP_PROFILE_SUFFIX; 1350 case ProfilingManager.PROFILING_TYPE_STACK_SAMPLING: 1351 return OUTPUT_FILE_STACK_SAMPLING_SUFFIX; 1352 case ProfilingManager.PROFILING_TYPE_SYSTEM_TRACE: 1353 return OUTPUT_FILE_UNREDACTED_TRACE_SUFFIX; 1354 default: 1355 throw new IllegalArgumentException("Invalid profiling type"); 1356 } 1357 } 1358 removeInvalidFilenameChars(String original)1359 private static String removeInvalidFilenameChars(String original) { 1360 if (TextUtils.isEmpty(original)) { 1361 return ""; 1362 } 1363 final StringBuilder sb = new StringBuilder(original.length()); 1364 for (int i = 0; i < original.length(); i++) { 1365 final char c = Character.toLowerCase(original.charAt(i)); 1366 if (isValidFilenameChar(c)) { 1367 sb.append(c); 1368 } 1369 } 1370 return sb.toString(); 1371 } 1372 isValidFilenameChar(char c)1373 private static boolean isValidFilenameChar(char c) { 1374 if (c >= 'a' && c <= 'z') { 1375 return true; 1376 } 1377 if (c >= '0' && c <= '9') { 1378 return true; 1379 } 1380 if (c == '-') { 1381 return true; 1382 } 1383 return false; 1384 } 1385 1386 private class ProfilingDeathRecipient implements IBinder.DeathRecipient { 1387 private final int mUid; 1388 ProfilingDeathRecipient(int uid)1389 ProfilingDeathRecipient(int uid) { 1390 mUid = uid; 1391 } 1392 1393 @Override binderDied()1394 public void binderDied() { 1395 if (DEBUG) Log.d(TAG, "binderDied without who should not have been called"); 1396 } 1397 1398 @Override binderDied(IBinder who)1399 public void binderDied(IBinder who) { 1400 // Synchronize because multiple binder died callbacks may occur simultaneously 1401 // on different threads and we want to ensure that when an app dies (i.e. all 1402 // binder objects die) we attempt to stop profiling exactly once. 1403 synchronized (mLock) { 1404 List<IProfilingResultCallback> callbacks = mResultCallbacks.get(mUid); 1405 1406 if (callbacks == null) { 1407 // No callbacks list for this uid, this likely means profiling was already 1408 // stopped (i.e. this is not the first binderDied call for this death). 1409 return; 1410 } 1411 1412 // Callbacks aren't valid anymore, remove the list. 1413 mResultCallbacks.remove(mUid); 1414 1415 // Finally, attempt to stop profiling. Once the profiling is stopped, processing 1416 // will continue as usual and will fail at copy to app storage which is the next 1417 // step that requires the now dead binder objects. The failure will result in the 1418 // session being added to {@link mQueueTracingResults} and being delivered to the 1419 // app the next time it registers a general listener. 1420 stopAllProfilingForUid(mUid); 1421 } 1422 } 1423 } 1424 1425 public static final class Lifecycle extends SystemService { 1426 final ProfilingService mService; 1427 Lifecycle(Context context)1428 public Lifecycle(Context context) { 1429 this(context, new ProfilingService(context)); 1430 } 1431 1432 @VisibleForTesting Lifecycle(Context context, ProfilingService service)1433 public Lifecycle(Context context, ProfilingService service) { 1434 super(context); 1435 mService = service; 1436 } 1437 1438 @Override onStart()1439 public void onStart() { 1440 try { 1441 publishBinderService("profiling_service", mService); 1442 } catch (Exception e) { 1443 if (DEBUG) Log.d(TAG, "Failed to publish service", e); 1444 } 1445 } 1446 1447 @Override onBootPhase(int phase)1448 public void onBootPhase(int phase) { 1449 super.onBootPhase(phase); 1450 } 1451 } 1452 } 1453