1 /* 2 * Copyright (C) 2022 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 com.android.adservices.service.stats; 18 19 import static android.adservices.common.AdServicesStatusUtils.STATUS_SUCCESS; 20 21 import static com.android.adservices.data.adselection.AdSelectionDatabase.DATABASE_NAME; 22 import static com.android.adservices.service.stats.AdServicesLoggerUtil.FIELD_UNSET; 23 import static com.android.adservices.service.stats.AdServicesStatsLog.RUN_AD_SCORING_PROCESS_REPORTED__GET_AD_SELECTION_LOGIC_SCRIPT_TYPE__JAVASCRIPT; 24 import static com.android.adservices.service.stats.AdServicesStatsLog.RUN_AD_SCORING_PROCESS_REPORTED__GET_AD_SELECTION_LOGIC_SCRIPT_TYPE__UNSET; 25 import static com.android.adservices.service.stats.AdsRelevanceStatusUtils.JS_RUN_STATUS_UNSET; 26 27 import android.adservices.common.AdSelectionSignals; 28 import android.adservices.common.CallerMetadata; 29 import android.annotation.NonNull; 30 import android.annotation.Nullable; 31 import android.content.Context; 32 33 import com.android.adservices.LoggerFactory; 34 import com.android.adservices.data.adselection.DBAdSelection; 35 import com.android.adservices.data.customaudience.DBCustomAudience; 36 import com.android.adservices.service.Flags; 37 import com.android.adservices.service.adselection.AdBiddingOutcome; 38 import com.android.adservices.service.common.BinderFlagReader; 39 import com.android.adservices.service.common.compat.FileCompatUtils; 40 import com.android.adservices.shared.util.Clock; 41 import com.android.internal.annotations.VisibleForTesting; 42 43 import java.nio.charset.StandardCharsets; 44 import java.util.List; 45 import java.util.Objects; 46 import java.util.stream.Collectors; 47 48 /** 49 * Class for logging the run ad selection process. It provides the functions to collect and log the 50 * corresponding ad selection process and its subcomponent processes and log the data into the 51 * statsd logs. This class collect data for the telemetry atoms: 52 * 53 * <ul> 54 * <li>RunAdBiddingProcessReportedStats for bidding stage: 55 * <ul> 56 * <li>Subprocess: 57 * <ul> 58 * <li>getBuyerCustomAudience 59 * <li>RunAdBidding 60 * </ul> 61 * </ul> 62 * <li>RunAdScoringProcessReportedStats for scoring stage: 63 * <ul> 64 * <li>Subprocess: 65 * <ul> 66 * <li>RunAdScoring 67 * <li>GetAdScores 68 * <li>scoreAds 69 * </ul> 70 * </ul> 71 * <li>RunAdSelectionProcessReportedStats for overall ad selection: 72 * <ul> 73 * <li>Subprocess: 74 * <ul> 75 * <li>persistAdSelection 76 * </ul> 77 * </ul> 78 * </ul> 79 * 80 * <p>Each complete parent process (bidding, scoring, and overall ad selection) should call its 81 * corresponding start and end methods to record its states and log the generated atom proto into 82 * the statsd logger. 83 * 84 * <p>Each subprocess should call its corresponding start method if it starts, and only call the end 85 * method for successful completion. In failure cases, the exceptions thrown should propagate to the 86 * end of the parent process, and unset ending timestamps will be clearly communicated in the logged 87 * atom. 88 */ 89 // TODO(b/259332713): Refactor the logger for individual bidding, scoring process etc. 90 public class AdSelectionExecutionLogger extends ApiServiceLatencyCalculator { 91 private static final LoggerFactory.Logger sLogger = LoggerFactory.getFledgeLogger(); 92 93 @VisibleForTesting 94 public static final int SCRIPT_JAVASCRIPT = 95 RUN_AD_SCORING_PROCESS_REPORTED__GET_AD_SELECTION_LOGIC_SCRIPT_TYPE__JAVASCRIPT; 96 97 @VisibleForTesting 98 static final int SCRIPT_UNSET = 99 RUN_AD_SCORING_PROCESS_REPORTED__GET_AD_SELECTION_LOGIC_SCRIPT_TYPE__UNSET; 100 101 @VisibleForTesting 102 static final String REPEATED_START_PERSIST_AD_SELECTION = 103 "The logger has already set the start of the persist-ad-selection process."; 104 105 @VisibleForTesting 106 static final String REPEATED_END_PERSIST_AD_SELECTION = 107 "The logger has already set the end of the persist-ad-selection process."; 108 109 @VisibleForTesting 110 static final String MISSING_START_PERSIST_AD_SELECTION = 111 "The logger should set the start of the persist-ad-selection process."; 112 113 @VisibleForTesting 114 static final String MISSING_END_PERSIST_AD_SELECTION = 115 "The logger should set the end of the persist-ad-selection process."; 116 117 @VisibleForTesting 118 static final String MISSING_PERSIST_AD_SELECTION = 119 "The ad selection execution logger should log the persist-ad-selection process."; 120 121 @VisibleForTesting 122 static final String REPEATED_END_BIDDING_STAGE = 123 "The logger has already set the end state of the bidding stage."; 124 125 @VisibleForTesting 126 static final String MISSING_START_RUN_AD_BIDDING = 127 "The logger should set the start of the run-ad-selection process."; 128 129 @VisibleForTesting 130 static final String REPEATED_START_BIDDING_STAGE = 131 "The logger has already set the start of the bidding stage."; 132 133 @VisibleForTesting 134 static final String REPEATED_END_GET_BUYERS_CUSTOM_AUDIENCE = 135 "The logger has already set the end of the get-buyers-custom-audience process."; 136 137 @VisibleForTesting 138 static final String MISSING_START_BIDDING_STAGE = 139 "The logger should set the start state of the bidding stage."; 140 141 @VisibleForTesting 142 static final String MISSING_END_GET_BUYERS_CUSTOM_AUDIENCE = 143 "The logger should set the end of the get-buyers-custom-audience process."; 144 145 @VisibleForTesting 146 static final String REPEATED_START_RUN_AD_BIDDING = 147 "The logger has already set the start of the run-ad-bidding process."; 148 149 @VisibleForTesting 150 static final String MISSING_GET_BUYERS_CUSTOM_AUDIENCE = 151 "The logger should set the start of the bidding stage and the " 152 + "get-buyers-custom-audience process."; 153 154 @VisibleForTesting static final float RATIO_OF_CAS_UNSET = -1.0f; 155 156 @VisibleForTesting 157 static final String REPEATED_START_RUN_AD_SCORING = 158 "The logger has already set the start of the run-ad-scoring process."; 159 160 @VisibleForTesting 161 static final String MISSING_START_RUN_AD_SCORING = 162 "The logger should set the start of the run-ad-scoring process."; 163 164 @VisibleForTesting 165 static final String REPEATED_END_RUN_AD_SCORING = 166 "The logger has already set the end of the run-ad-scoring process."; 167 168 @VisibleForTesting 169 static final String MISSING_START_GET_AD_SELECTION_LOGIC = 170 "The logger should set the start of the get-ad-selection-logic process."; 171 172 @VisibleForTesting 173 static final String REPEATED_END_GET_AD_SELECTION_LOGIC = 174 "The logger has already set the end of the get-ad-selection-logic process."; 175 176 @VisibleForTesting 177 static final String REPEATED_START_GET_TRUSTED_SCORING_SIGNALS = 178 "The logger has already set the start of the get-trusted-scoring-signals process."; 179 180 @VisibleForTesting 181 static final String MISSING_START_GET_TRUSTED_SCORING_SIGNALS = 182 "The logger should set the start of the get-trusted-scoring-signals process."; 183 184 @VisibleForTesting 185 static final String REPEATED_END_GET_TRUSTED_SCORING_SIGNALS = 186 "The logger has already set the end of the get-trusted-scoring-signals process."; 187 188 @VisibleForTesting 189 static final String REPEATED_START_SCORE_ADS = 190 "The logger has already set the start of the score-ads process."; 191 192 @VisibleForTesting 193 static final String MISSING_START_SCORE_ADS = 194 "The logger should set the start of the score-ads process."; 195 196 @VisibleForTesting 197 static final String REPEATED_END_SCORE_ADS = 198 "The logger has already set the end of the score-ads process."; 199 200 @VisibleForTesting 201 static final String REPEATED_START_GET_AD_SELECTION_LOGIC = 202 "The logger has already set the start of the get-ad-selection-logic process."; 203 204 @VisibleForTesting 205 static final String MISSING_GET_TRUSTED_SCORING_SIGNALS_PROCESS = 206 "The logger should set the get-trusted-scoring-signals process."; 207 208 @VisibleForTesting 209 static final String MISSING_END_SCORE_ADS = 210 "The logger should set the end of the score-ads process."; 211 212 @VisibleForTesting 213 static final String REPEATED_START_GET_AD_SCORES = 214 "The logger has already set the get-ad-scores progress."; 215 216 @VisibleForTesting 217 static final String MISSING_START_GET_AD_SCORES = 218 "The logger should set the start of the get-ad-scores process."; 219 220 @VisibleForTesting 221 static final String REPEATED_END_GET_AD_SCORES = 222 "The logger has already set the ned of the get-ad-scores process."; 223 224 @VisibleForTesting 225 static final String MISSING_END_GET_AD_SELECTION_LOGIC = 226 "The logger should set the end of the get-ad-selection-logic process."; 227 228 private final Context mContext; 229 private final long mBinderElapsedTimestamp; 230 231 // Bidding stage. 232 private long mBiddingStageStartTimestamp; 233 private long mGetBuyersCustomAudienceEndTimestamp; 234 private long mRunAdBiddingStartTimestamp; 235 private long mRunAdBiddingEndTimestamp; 236 private long mBiddingStageEndTimestamp; 237 private int mNumBuyersRequested; 238 private int mNumBuyersFetched; 239 private int mNumOfAdsEnteringBidding; 240 private int mNumOfCAsEnteringBidding; 241 private int mNumOfCAsPostBidding; 242 243 // Scoring stage. 244 private long mRunAdScoringStartTimestamp; 245 private int mNumOfCAsEnteringScoring; 246 private int mNumOfRmktAdsEnteringScoring; 247 private long mGetAdSelectionLogicStartTimestamp; 248 private long mGetAdSelectionLogicEndTimestamp; 249 private int mGetAdSelectionLogicScriptSizeInBytes; 250 private long mGetAdScoresStartTimestamp; 251 private long mGetTrustedScoringSignalsStartTimestamp; 252 private long mGetTrustedScoringSignalsEndTimestamp; 253 private int mFetchedTrustedScoringSignalsDataSizeInBytes; 254 private long mGetAdScoresEndTimestamp; 255 private long mScoreAdsStartTimestamp; 256 private long mScoreAdsEndTimestamp; 257 private long mRunAdScoringEndTimestamp; 258 259 // Persist ad selection. 260 private boolean mIsRemarketingAdsWon; 261 private long mPersistAdSelectionStartTimestamp; 262 private long mPersistAdSelectionEndTimestamp; 263 private long mDBAdSelectionSizeInBytes; 264 265 private AdServicesLogger mAdServicesLogger; 266 private final boolean mDataHeaderMetricsEnabled; 267 private final boolean mJsScriptResultCodeMetricsEnabled; 268 269 private boolean mScoreAdSellerAdditionalSignalsContainedDataVersion; 270 private int mScoreAdJsScriptResultCode; 271 AdSelectionExecutionLogger( @onNull CallerMetadata callerMetadata, @NonNull Clock clock, @NonNull Context context, @NonNull AdServicesLogger adServicesLogger, @NonNull Flags flags)272 public AdSelectionExecutionLogger( 273 @NonNull CallerMetadata callerMetadata, 274 @NonNull Clock clock, 275 @NonNull Context context, 276 @NonNull AdServicesLogger adServicesLogger, 277 @NonNull Flags flags) { 278 super(clock); 279 Objects.requireNonNull(callerMetadata); 280 Objects.requireNonNull(clock); 281 Objects.requireNonNull(context); 282 Objects.requireNonNull(adServicesLogger); 283 Objects.requireNonNull(flags); 284 this.mBinderElapsedTimestamp = callerMetadata.getBinderElapsedTimestamp(); 285 this.mContext = context; 286 this.mAdServicesLogger = adServicesLogger; 287 this.mDataHeaderMetricsEnabled = 288 BinderFlagReader.readFlag(flags::getFledgeDataVersionHeaderMetricsEnabled); 289 this.mJsScriptResultCodeMetricsEnabled = 290 BinderFlagReader.readFlag(flags::getFledgeJsScriptResultCodeMetricsEnabled); 291 this.mScoreAdJsScriptResultCode = JS_RUN_STATUS_UNSET; 292 sLogger.v("AdSelectionExecutionLogger starts."); 293 } 294 295 /** records the start state of a bidding process. */ startBiddingProcess(int numBuyersRequested)296 public void startBiddingProcess(int numBuyersRequested) throws IllegalStateException { 297 if (mBiddingStageStartTimestamp > 0L) { 298 throw new IllegalStateException(REPEATED_START_BIDDING_STAGE); 299 } 300 sLogger.v("Start the bidding process."); 301 this.mBiddingStageStartTimestamp = getServiceElapsedTimestamp(); 302 this.mNumBuyersRequested = numBuyersRequested; 303 sLogger.v("The bidding process start timestamp is %d", mBiddingStageStartTimestamp); 304 sLogger.v("With number of buyers requested: %d", mNumBuyersRequested); 305 } 306 307 /** records the end state of a successful get-buyers-custom-audience process. */ endGetBuyersCustomAudience(int numBuyersFetched)308 public void endGetBuyersCustomAudience(int numBuyersFetched) throws IllegalStateException { 309 if (mBiddingStageStartTimestamp == 0L) { 310 throw new IllegalStateException((MISSING_START_BIDDING_STAGE)); 311 } 312 if (mGetBuyersCustomAudienceEndTimestamp > 0L) { 313 throw new IllegalStateException(REPEATED_END_GET_BUYERS_CUSTOM_AUDIENCE); 314 } 315 sLogger.v("End the get-buyers-custom-audience process."); 316 this.mGetBuyersCustomAudienceEndTimestamp = getServiceElapsedTimestamp(); 317 this.mNumBuyersFetched = numBuyersFetched; 318 sLogger.v( 319 "The get-buyers-custom-audience process ends at %d with" 320 + " num of buyers fetched %d:", 321 mGetBuyersCustomAudienceEndTimestamp, mNumBuyersFetched); 322 } 323 324 /** records the start state of the run-ad-bidding process. */ startRunAdBidding(@onNull List<DBCustomAudience> customAudiences)325 public void startRunAdBidding(@NonNull List<DBCustomAudience> customAudiences) 326 throws IllegalStateException { 327 Objects.requireNonNull(customAudiences); 328 if (mBiddingStageStartTimestamp == 0L || mGetBuyersCustomAudienceEndTimestamp == 0L) { 329 throw new IllegalStateException(MISSING_GET_BUYERS_CUSTOM_AUDIENCE); 330 } 331 if (mRunAdBiddingStartTimestamp > 0L) { 332 throw new IllegalStateException(REPEATED_START_RUN_AD_BIDDING); 333 } 334 sLogger.v("Starts the run-ad-bidding process."); 335 this.mRunAdBiddingStartTimestamp = getServiceElapsedTimestamp(); 336 if (customAudiences.isEmpty()) return; 337 this.mNumOfAdsEnteringBidding = 338 customAudiences.stream() 339 .filter(a -> Objects.nonNull(a)) 340 .map(a -> a.getAds().size()) 341 .reduce(0, (a, b) -> a + b); 342 this.mNumOfCAsEnteringBidding = customAudiences.size(); 343 sLogger.v( 344 "Entering bidding NO of Ads: %d:, NO of CAs : %d", 345 mNumOfAdsEnteringBidding, mNumOfCAsEnteringBidding); 346 } 347 348 /** 349 * records the end state of the bidding process and log the generated {@link 350 * RunAdBiddingProcessReportedStats} into the {@link AdServicesLogger}. 351 */ endBiddingProcess(@ullable List<AdBiddingOutcome> result, int resultCode)352 public void endBiddingProcess(@Nullable List<AdBiddingOutcome> result, int resultCode) 353 throws IllegalStateException { 354 sLogger.v("End the BiddingProcess with resultCode %d.", resultCode); 355 // The start of the get-buyers-custom-audience must be set as the start of the bidding 356 // process. 357 if (mBiddingStageStartTimestamp == 0L) { 358 throw new IllegalStateException(MISSING_START_BIDDING_STAGE); 359 } 360 if (mBiddingStageEndTimestamp > 0L) { 361 throw new IllegalStateException(REPEATED_END_BIDDING_STAGE); 362 } 363 if (resultCode == STATUS_SUCCESS) { 364 // Throws IllegalStateException if the buyers-custom-audience process has not been 365 // set correctly. 366 if (mGetBuyersCustomAudienceEndTimestamp == 0L) { 367 throw new IllegalStateException(MISSING_END_GET_BUYERS_CUSTOM_AUDIENCE); 368 } else if (mRunAdBiddingStartTimestamp == 0L) { 369 throw new IllegalStateException(MISSING_START_RUN_AD_BIDDING); 370 } else if (mRunAdBiddingEndTimestamp > 0L || mBiddingStageEndTimestamp > 0L) { 371 throw new IllegalStateException(REPEATED_END_BIDDING_STAGE); 372 } 373 this.mRunAdBiddingEndTimestamp = getServiceElapsedTimestamp(); 374 this.mBiddingStageEndTimestamp = mRunAdBiddingEndTimestamp; 375 this.mNumOfCAsPostBidding = 376 result.stream() 377 .filter(Objects::nonNull) 378 .map(a -> a.getCustomAudienceBiddingInfo()) 379 .filter(Objects::nonNull) 380 .map(a -> a.getCustomAudienceSignals().hashCode()) 381 .collect(Collectors.toSet()) 382 .size(); 383 sLogger.v( 384 "Ends of a successful run-ad-bidding process with num of CAs post " 385 + "bidding %d. with end timestamp: %d ", 386 mNumOfCAsPostBidding, mRunAdBiddingEndTimestamp); 387 } else { 388 sLogger.v("Ends of a failed run-ad-bidding process."); 389 this.mBiddingStageEndTimestamp = getServiceElapsedTimestamp(); 390 } 391 sLogger.v("Log the AdRunBiddingProcessReportedStats to the AdServicesLog."); 392 RunAdBiddingProcessReportedStats runAdBiddingProcessReportedStats = 393 getRunAdBiddingProcessReportedStats(resultCode); 394 mAdServicesLogger.logRunAdBiddingProcessReportedStats(runAdBiddingProcessReportedStats); 395 } 396 397 /** start the run-ad-scoring process. */ startRunAdScoring(List<AdBiddingOutcome> adBiddingOutcomes)398 public void startRunAdScoring(List<AdBiddingOutcome> adBiddingOutcomes) 399 throws IllegalStateException { 400 if (mRunAdScoringStartTimestamp > 0L) { 401 throw new IllegalStateException(REPEATED_START_RUN_AD_SCORING); 402 } 403 sLogger.v("Start the run-ad-scoring process."); 404 this.mRunAdScoringStartTimestamp = getServiceElapsedTimestamp(); 405 this.mNumOfRmktAdsEnteringScoring = 406 adBiddingOutcomes.stream() 407 .filter(Objects::nonNull) 408 .map(AdBiddingOutcome::getAdWithBid) 409 .filter(Objects::nonNull) 410 .collect(Collectors.toSet()) 411 .size(); 412 this.mNumOfCAsEnteringScoring = 413 adBiddingOutcomes.stream() 414 .filter(Objects::nonNull) 415 .map(a -> a.getCustomAudienceBiddingInfo()) 416 .filter(Objects::nonNull) 417 .map(a -> a.getCustomAudienceSignals().hashCode()) 418 .collect(Collectors.toSet()) 419 .size(); 420 } 421 422 /** start the get-ad-selection-logic process. */ startGetAdSelectionLogic()423 public void startGetAdSelectionLogic() throws IllegalStateException { 424 if (mRunAdScoringStartTimestamp == 0L) { 425 throw new IllegalStateException(MISSING_START_RUN_AD_SCORING); 426 } 427 if (mGetAdSelectionLogicStartTimestamp > 0L) { 428 throw new IllegalStateException(REPEATED_START_GET_AD_SELECTION_LOGIC); 429 } 430 sLogger.v("Start the get-ad-selection-logic process."); 431 this.mGetAdSelectionLogicStartTimestamp = getServiceElapsedTimestamp(); 432 } 433 434 /** end a successful get-ad-selection-logic process. */ endGetAdSelectionLogic(@onNull String adSelectionLogic)435 public void endGetAdSelectionLogic(@NonNull String adSelectionLogic) 436 throws IllegalStateException { 437 if (mGetAdSelectionLogicStartTimestamp == 0L) { 438 throw new IllegalStateException(MISSING_START_GET_AD_SELECTION_LOGIC); 439 } 440 if (mGetAdSelectionLogicEndTimestamp > 0L) { 441 throw new IllegalStateException(REPEATED_END_GET_AD_SELECTION_LOGIC); 442 } 443 sLogger.v("End a successful get-ad-selection-logic process."); 444 this.mGetAdSelectionLogicScriptSizeInBytes = 445 adSelectionLogic.getBytes(StandardCharsets.UTF_8).length; 446 this.mGetAdSelectionLogicEndTimestamp = getServiceElapsedTimestamp(); 447 } 448 449 /** start the get-ad-scores process. */ startGetAdScores()450 public void startGetAdScores() throws IllegalStateException { 451 if (mGetAdSelectionLogicEndTimestamp == 0L) { 452 throw new IllegalStateException(MISSING_END_GET_AD_SELECTION_LOGIC); 453 } 454 if (mGetAdScoresStartTimestamp > 0L) { 455 throw new IllegalStateException(REPEATED_START_GET_AD_SCORES); 456 } 457 sLogger.v("Start the get-ad-scores process."); 458 this.mGetAdScoresStartTimestamp = getServiceElapsedTimestamp(); 459 } 460 461 /** start the get-trusted-scoring-signals process. */ startGetTrustedScoringSignals()462 public void startGetTrustedScoringSignals() throws IllegalStateException { 463 if (mGetAdScoresStartTimestamp == 0L) { 464 throw new IllegalStateException(MISSING_START_GET_AD_SCORES); 465 } 466 if (mGetTrustedScoringSignalsStartTimestamp > 0L) { 467 throw new IllegalStateException(REPEATED_START_GET_TRUSTED_SCORING_SIGNALS); 468 } 469 sLogger.v("Starts the get-trusted-scoring-signals."); 470 this.mGetTrustedScoringSignalsStartTimestamp = getServiceElapsedTimestamp(); 471 } 472 473 /** end a successful get-trusted-scoring-signals process. */ endGetTrustedScoringSignals(@onNull AdSelectionSignals adSelectionSignals)474 public void endGetTrustedScoringSignals(@NonNull AdSelectionSignals adSelectionSignals) 475 throws IllegalStateException { 476 if (mGetTrustedScoringSignalsStartTimestamp == 0L) { 477 throw new IllegalStateException(MISSING_START_GET_TRUSTED_SCORING_SIGNALS); 478 } 479 if (mGetTrustedScoringSignalsEndTimestamp > 0L) { 480 throw new IllegalStateException(REPEATED_END_GET_TRUSTED_SCORING_SIGNALS); 481 } 482 sLogger.v("End a successful get-trusted-signals process."); 483 this.mFetchedTrustedScoringSignalsDataSizeInBytes = 484 adSelectionSignals.toString().getBytes(StandardCharsets.UTF_8).length; 485 this.mGetTrustedScoringSignalsEndTimestamp = getServiceElapsedTimestamp(); 486 } 487 488 /** start scoreAds script execution process. */ startScoreAds()489 public void startScoreAds() throws IllegalStateException { 490 if (mGetTrustedScoringSignalsEndTimestamp == 0L) { 491 throw new IllegalStateException(MISSING_GET_TRUSTED_SCORING_SIGNALS_PROCESS); 492 } 493 if (mScoreAdsStartTimestamp > 0L) { 494 throw new IllegalStateException(REPEATED_START_SCORE_ADS); 495 } 496 sLogger.v("Start the execution of the scoreAds script."); 497 this.mScoreAdsStartTimestamp = getServiceElapsedTimestamp(); 498 } 499 500 /** end a complete execution of the scoreAds script. */ endScoreAds()501 public void endScoreAds() throws IllegalStateException { 502 if (mScoreAdsStartTimestamp == 0L) throw new IllegalStateException(MISSING_START_SCORE_ADS); 503 if (mScoreAdsEndTimestamp > 0L) { 504 throw new IllegalStateException(REPEATED_END_SCORE_ADS); 505 } 506 sLogger.v("End the execution of the scoreAds script successfully."); 507 this.mScoreAdsEndTimestamp = getServiceElapsedTimestamp(); 508 } 509 510 /** end a successful get-ad-scores process. */ endGetAdScores()511 public void endGetAdScores() throws IllegalStateException { 512 if (mScoreAdsEndTimestamp == 0L) { 513 throw new IllegalStateException(MISSING_END_SCORE_ADS); 514 } 515 if (mGetAdScoresEndTimestamp > 0L) { 516 throw new IllegalStateException(REPEATED_END_GET_AD_SCORES); 517 } 518 sLogger.v("End the get-ad-scores process."); 519 this.mGetAdScoresEndTimestamp = getServiceElapsedTimestamp(); 520 } 521 522 /** 523 * end a run-ad-scoring process and log the {@link RunAdScoringProcessReportedStats} atom into 524 * the {@link AdServicesLogger}. 525 */ endRunAdScoring(int resultCode)526 public void endRunAdScoring(int resultCode) throws IllegalStateException { 527 if (mRunAdScoringStartTimestamp == 0L) { 528 throw new IllegalStateException(MISSING_START_RUN_AD_SCORING); 529 } 530 if (mRunAdScoringEndTimestamp > 0L) { 531 throw new IllegalStateException(REPEATED_END_RUN_AD_SCORING); 532 } 533 sLogger.v("End Running Ad Scoring."); 534 this.mRunAdScoringEndTimestamp = getServiceElapsedTimestamp(); 535 RunAdScoringProcessReportedStats runAdScoringProcessReportedStats = 536 getRunAdScoringProcessReportedStats(resultCode); 537 sLogger.v("Log the RunAdScoringProcessReportedStats into the AdServicesLogger."); 538 mAdServicesLogger.logRunAdScoringProcessReportedStats(runAdScoringProcessReportedStats); 539 } 540 541 /** records the start state of the persist-ad-selection process. */ startPersistAdSelection(DBAdSelection dbAdSelection)542 public void startPersistAdSelection(DBAdSelection dbAdSelection) throws IllegalStateException { 543 if (mPersistAdSelectionStartTimestamp > 0L) { 544 throw new IllegalStateException(REPEATED_START_PERSIST_AD_SELECTION); 545 } 546 sLogger.v("Starts the persisting ad selection."); 547 this.mIsRemarketingAdsWon = Objects.nonNull(dbAdSelection.getBiddingLogicUri()); 548 this.mPersistAdSelectionStartTimestamp = getServiceElapsedTimestamp(); 549 } 550 551 /** records the end state of a finished persist-ad-selection process. */ endPersistAdSelection()552 public void endPersistAdSelection() throws IllegalStateException { 553 if (mPersistAdSelectionStartTimestamp == 0L) { 554 throw new IllegalStateException(MISSING_START_PERSIST_AD_SELECTION); 555 } 556 if (mPersistAdSelectionEndTimestamp > 0L) { 557 throw new IllegalStateException(REPEATED_END_PERSIST_AD_SELECTION); 558 } 559 sLogger.v("Ends the persisting ad selection."); 560 this.mPersistAdSelectionEndTimestamp = getServiceElapsedTimestamp(); 561 this.mDBAdSelectionSizeInBytes = 562 FileCompatUtils.getDatabasePathHelper(mContext, DATABASE_NAME).length(); 563 sLogger.v("The persistAdSelection end timestamp is %d:", mPersistAdSelectionEndTimestamp); 564 sLogger.v("The database file size is %d", mDBAdSelectionSizeInBytes); 565 } 566 567 /** Record whether ScoreAd SellerAdditionalSignals contained Data Version. */ setScoreAdSellerAdditionalSignalsContainedDataVersion(boolean value)568 public void setScoreAdSellerAdditionalSignalsContainedDataVersion(boolean value) { 569 if (mDataHeaderMetricsEnabled) { 570 this.mScoreAdSellerAdditionalSignalsContainedDataVersion = value; 571 } 572 } 573 574 /** Record the ScoreAd JsScript Result Code. */ setScoreAdJsScriptResultCode(@dsRelevanceStatusUtils.JsRunStatus int resultCode)575 public void setScoreAdJsScriptResultCode(@AdsRelevanceStatusUtils.JsRunStatus int resultCode) { 576 if (mJsScriptResultCodeMetricsEnabled) { 577 this.mScoreAdJsScriptResultCode = resultCode; 578 } 579 } 580 581 /** 582 * This method should be called at the end of an ad selection process to generate and log the 583 * {@link RunAdSelectionProcessReportedStats} into the {@link AdServicesLogger}. 584 */ close(int resultCode)585 public void close(int resultCode) throws IllegalStateException { 586 sLogger.v("Log the RunAdSelectionProcessReportedStats to the AdServicesLog."); 587 if (resultCode == STATUS_SUCCESS) { 588 if (mPersistAdSelectionStartTimestamp == 0L 589 && mPersistAdSelectionEndTimestamp == 0L 590 && mDBAdSelectionSizeInBytes == 0L) { 591 throw new IllegalStateException(MISSING_PERSIST_AD_SELECTION); 592 } else if (mPersistAdSelectionEndTimestamp == 0L || mDBAdSelectionSizeInBytes == 0L) { 593 throw new IllegalStateException(MISSING_END_PERSIST_AD_SELECTION); 594 } 595 sLogger.v( 596 "Log RunAdSelectionProcessReportedStats for a successful ad selection " 597 + "run."); 598 } else { 599 sLogger.v("Log RunAdSelectionProcessReportedStats for a failed ad selection run."); 600 } 601 RunAdSelectionProcessReportedStats runAdSelectionProcessReportedStats = 602 getRunAdSelectionProcessReportedStats( 603 resultCode, getApiServiceInternalFinalLatencyInMs()); 604 mAdServicesLogger.logRunAdSelectionProcessReportedStats(runAdSelectionProcessReportedStats); 605 } 606 607 /** @return the overall latency in milliseconds of selectAds called by the client interface. */ getRunAdSelectionOverallLatencyInMs()608 public int getRunAdSelectionOverallLatencyInMs() { 609 return getBinderLatencyInMs(mBinderElapsedTimestamp) 610 + getApiServiceInternalFinalLatencyInMs(); 611 } 612 getRunAdSelectionProcessReportedStats( int runAdSelectionResultCode, int runAdSelectionLatencyInMs)613 private RunAdSelectionProcessReportedStats getRunAdSelectionProcessReportedStats( 614 int runAdSelectionResultCode, int runAdSelectionLatencyInMs) { 615 return RunAdSelectionProcessReportedStats.builder() 616 .setIsRemarketingAdsWon(mIsRemarketingAdsWon) 617 .setDBAdSelectionSizeInBytes(getDbAdSelectionSizeInBytes()) 618 .setPersistAdSelectionLatencyInMillis(getPersistAdSelectionLatencyInMs()) 619 .setPersistAdSelectionResultCode( 620 getPersistAdSelectionResultCode(runAdSelectionResultCode)) 621 .setRunAdSelectionLatencyInMillis(runAdSelectionLatencyInMs) 622 .setRunAdSelectionResultCode(runAdSelectionResultCode) 623 .build(); 624 } 625 getRunAdBiddingProcessReportedStats(int resultCode)626 private RunAdBiddingProcessReportedStats getRunAdBiddingProcessReportedStats(int resultCode) { 627 return RunAdBiddingProcessReportedStats.builder() 628 .setGetBuyersCustomAudienceLatencyInMills(getGetBuyersCustomAudienceLatencyInMs()) 629 .setGetBuyersCustomAudienceResultCode( 630 getGetBuyersCustomAudienceResultCode(resultCode)) 631 .setNumBuyersRequested(getNumBuyersRequested()) 632 .setNumBuyersFetched(getNumBuyersFetched()) 633 .setNumOfAdsEnteringBidding(getNumOfAdsEnteringBidding()) 634 .setNumOfCasEnteringBidding(getNumOfCAsEnteringBidding()) 635 .setNumOfCasPostBidding(getNumOfCAsPostBidding()) 636 .setRatioOfCasSelectingRmktAds(getRatioOfCasSelectingRmktAds()) 637 .setRunAdBiddingLatencyInMillis(getRunAdBiddingLatencyInMs()) 638 .setRunAdBiddingResultCode(getRunAdBiddingResultCode(resultCode)) 639 .setTotalAdBiddingStageLatencyInMillis(getTotalAdBiddingStageLatencyInMs()) 640 .build(); 641 } 642 getRunAdScoringProcessReportedStats(int resultCode)643 private RunAdScoringProcessReportedStats getRunAdScoringProcessReportedStats(int resultCode) { 644 return RunAdScoringProcessReportedStats.builder() 645 .setGetAdSelectionLogicLatencyInMillis(getAdSelectionLogicLatencyInMs()) 646 .setGetAdSelectionLogicResultCode(getGetAdSelectionLogicResultCode(resultCode)) 647 .setGetAdSelectionLogicScriptType(getGetAdSelectionLogicScriptType()) 648 .setFetchedAdSelectionLogicScriptSizeInBytes( 649 getFetchedAdSelectionLogicScriptSizeInBytes()) 650 .setGetTrustedScoringSignalsLatencyInMillis( 651 getGetTrustedScoringSignalsLatencyInMs()) 652 .setGetTrustedScoringSignalsResultCode( 653 getGetTrustedScoringSignalsResultCode(resultCode)) 654 .setFetchedTrustedScoringSignalsDataSizeInBytes( 655 getFetchedTrustedScoringSignalsDataSizeInBytes()) 656 .setScoreAdsLatencyInMillis(getScoreAdsLatencyInMs()) 657 .setGetAdScoresLatencyInMillis(getAdScoresLatencyInMs()) 658 .setGetAdScoresResultCode(getAdScoresResultCode(resultCode)) 659 .setNumOfCasEnteringScoring(getNumOfCAsEnteringScoring()) 660 .setNumOfRemarketingAdsEnteringScoring(getNumOfRemarketingAdsEnteringScoring()) 661 .setNumOfContextualAdsEnteringScoring(FIELD_UNSET) 662 .setRunAdScoringLatencyInMillis(getRunScoringLatencyInMs()) 663 .setRunAdScoringResultCode(resultCode) 664 .setScoreAdSellerAdditionalSignalsContainedDataVersion( 665 mScoreAdSellerAdditionalSignalsContainedDataVersion) 666 .setScoreAdJsScriptResultCode(mScoreAdJsScriptResultCode) 667 .build(); 668 } 669 getGetAdSelectionLogicScriptType()670 private int getGetAdSelectionLogicScriptType() { 671 if (mGetAdSelectionLogicEndTimestamp > 0L) return SCRIPT_JAVASCRIPT; 672 return SCRIPT_UNSET; 673 } 674 getRunScoringLatencyInMs()675 private int getRunScoringLatencyInMs() { 676 if (mRunAdScoringStartTimestamp == 0L) { 677 return FIELD_UNSET; 678 } 679 return (int) (mRunAdScoringEndTimestamp - mRunAdScoringStartTimestamp); 680 } 681 getNumOfCAsEnteringScoring()682 private int getNumOfCAsEnteringScoring() { 683 if (mRunAdScoringStartTimestamp == 0L) { 684 return FIELD_UNSET; 685 } 686 return mNumOfCAsEnteringScoring; 687 } 688 getNumOfRemarketingAdsEnteringScoring()689 private int getNumOfRemarketingAdsEnteringScoring() { 690 if (mRunAdScoringStartTimestamp == 0L) { 691 return FIELD_UNSET; 692 } 693 return mNumOfRmktAdsEnteringScoring; 694 } 695 getAdScoresResultCode(int resultCode)696 private int getAdScoresResultCode(int resultCode) { 697 if (mGetAdScoresStartTimestamp == 0L) { 698 return FIELD_UNSET; 699 } 700 if (mGetAdScoresEndTimestamp == 0L) { 701 return resultCode; 702 } 703 return STATUS_SUCCESS; 704 } 705 getAdScoresLatencyInMs()706 private int getAdScoresLatencyInMs() { 707 if (mGetAdScoresStartTimestamp == 0L) { 708 return FIELD_UNSET; 709 } 710 if (mGetAdScoresEndTimestamp == 0L) { 711 return (int) (mRunAdScoringEndTimestamp - mGetAdScoresStartTimestamp); 712 } 713 return (int) (mGetAdScoresEndTimestamp - mGetAdScoresStartTimestamp); 714 } 715 getScoreAdsLatencyInMs()716 private int getScoreAdsLatencyInMs() { 717 if (mScoreAdsStartTimestamp == 0L) { 718 return FIELD_UNSET; 719 } else if (mScoreAdsEndTimestamp == 0L) { 720 return (int) (mRunAdScoringEndTimestamp - mScoreAdsStartTimestamp); 721 } 722 return (int) (mScoreAdsEndTimestamp - mScoreAdsStartTimestamp); 723 } 724 getFetchedTrustedScoringSignalsDataSizeInBytes()725 private int getFetchedTrustedScoringSignalsDataSizeInBytes() { 726 if (mGetTrustedScoringSignalsEndTimestamp > 0L) { 727 return mFetchedTrustedScoringSignalsDataSizeInBytes; 728 } 729 return FIELD_UNSET; 730 } 731 getGetTrustedScoringSignalsResultCode(int resultCode)732 private int getGetTrustedScoringSignalsResultCode(int resultCode) { 733 if (mGetTrustedScoringSignalsStartTimestamp == 0L) { 734 return FIELD_UNSET; 735 } else if (mGetTrustedScoringSignalsEndTimestamp > 0L) { 736 return STATUS_SUCCESS; 737 } 738 return resultCode; 739 } 740 getGetTrustedScoringSignalsLatencyInMs()741 private int getGetTrustedScoringSignalsLatencyInMs() { 742 if (mGetTrustedScoringSignalsStartTimestamp == 0L) { 743 return FIELD_UNSET; 744 } else if (mGetTrustedScoringSignalsEndTimestamp == 0L) { 745 return (int) (mRunAdScoringEndTimestamp - mGetTrustedScoringSignalsStartTimestamp); 746 } 747 return (int) 748 (mGetTrustedScoringSignalsEndTimestamp - mGetTrustedScoringSignalsStartTimestamp); 749 } 750 getFetchedAdSelectionLogicScriptSizeInBytes()751 private int getFetchedAdSelectionLogicScriptSizeInBytes() { 752 if (mGetAdSelectionLogicEndTimestamp > 0) { 753 return mGetAdSelectionLogicScriptSizeInBytes; 754 } 755 return FIELD_UNSET; 756 } 757 getGetAdSelectionLogicResultCode(int resultCode)758 private int getGetAdSelectionLogicResultCode(int resultCode) { 759 if (mGetAdSelectionLogicStartTimestamp == 0L) { 760 return FIELD_UNSET; 761 } else if (mGetAdSelectionLogicEndTimestamp > 0L) { 762 return STATUS_SUCCESS; 763 } 764 return resultCode; 765 } 766 getAdSelectionLogicLatencyInMs()767 private int getAdSelectionLogicLatencyInMs() { 768 if (mGetAdSelectionLogicStartTimestamp == 0L) { 769 return FIELD_UNSET; 770 } else if (mGetAdSelectionLogicEndTimestamp == 0L) { 771 return (int) (mRunAdScoringEndTimestamp - mGetAdSelectionLogicStartTimestamp); 772 } 773 return (int) (mGetAdSelectionLogicEndTimestamp - mGetAdSelectionLogicStartTimestamp); 774 } 775 getNumBuyersFetched()776 private int getNumBuyersFetched() { 777 if (mGetBuyersCustomAudienceEndTimestamp > 0L) { 778 return mNumBuyersFetched; 779 } 780 return FIELD_UNSET; 781 } 782 getNumBuyersRequested()783 private int getNumBuyersRequested() { 784 if (mBiddingStageStartTimestamp > 0L) { 785 return mNumBuyersRequested; 786 } 787 return FIELD_UNSET; 788 } 789 getNumOfAdsEnteringBidding()790 private int getNumOfAdsEnteringBidding() { 791 if (mRunAdBiddingStartTimestamp > 0L) { 792 return mNumOfAdsEnteringBidding; 793 } 794 return FIELD_UNSET; 795 } 796 getNumOfCAsEnteringBidding()797 private int getNumOfCAsEnteringBidding() { 798 if (mRunAdBiddingStartTimestamp > 0L) { 799 return mNumOfCAsEnteringBidding; 800 } 801 return FIELD_UNSET; 802 } 803 getNumOfCAsPostBidding()804 private int getNumOfCAsPostBidding() { 805 if (mRunAdBiddingEndTimestamp > 0L) { 806 return mNumOfCAsPostBidding; 807 } 808 return FIELD_UNSET; 809 } 810 getRatioOfCasSelectingRmktAds()811 private float getRatioOfCasSelectingRmktAds() { 812 if (mRunAdBiddingEndTimestamp > 0L) { 813 return ((float) mNumOfCAsPostBidding) / mNumOfCAsEnteringBidding; 814 } 815 return RATIO_OF_CAS_UNSET; 816 } 817 getDbAdSelectionSizeInBytes()818 private int getDbAdSelectionSizeInBytes() { 819 if (mPersistAdSelectionEndTimestamp > 0L) { 820 return (int) mDBAdSelectionSizeInBytes; 821 } 822 return FIELD_UNSET; 823 } 824 getGetBuyersCustomAudienceResultCode(int resultCode)825 private int getGetBuyersCustomAudienceResultCode(int resultCode) { 826 if (mBiddingStageStartTimestamp == 0) { 827 return FIELD_UNSET; 828 } 829 if (mGetBuyersCustomAudienceEndTimestamp > 0L) { 830 return STATUS_SUCCESS; 831 } 832 return resultCode; 833 } 834 getRunAdBiddingResultCode(int resultCode)835 private int getRunAdBiddingResultCode(int resultCode) { 836 if (mRunAdBiddingStartTimestamp == 0L) { 837 return FIELD_UNSET; 838 } else if (mRunAdBiddingEndTimestamp > 0L) { 839 return STATUS_SUCCESS; 840 } 841 return resultCode; 842 } 843 getPersistAdSelectionResultCode(int resultCode)844 private int getPersistAdSelectionResultCode(int resultCode) { 845 if (mPersistAdSelectionStartTimestamp == 0L) { 846 return FIELD_UNSET; 847 } else if (mPersistAdSelectionEndTimestamp > 0L) { 848 return STATUS_SUCCESS; 849 } 850 return resultCode; 851 } 852 853 /** 854 * @return the latency in milliseconds of the get-buyers-custom-audience process if started, 855 * otherwise the {@link AdServicesLoggerUtil#FIELD_UNSET}. 856 */ getGetBuyersCustomAudienceLatencyInMs()857 private int getGetBuyersCustomAudienceLatencyInMs() { 858 if (mBiddingStageStartTimestamp == 0L) { 859 return FIELD_UNSET; 860 } else if (mGetBuyersCustomAudienceEndTimestamp == 0L) { 861 return (int) (mBiddingStageEndTimestamp - mBiddingStageStartTimestamp); 862 } 863 return (int) (mGetBuyersCustomAudienceEndTimestamp - mBiddingStageStartTimestamp); 864 } 865 866 /** 867 * @return the latency in milliseconds of the run-ad-bidding process if started, otherwise the 868 * {@link AdServicesLoggerUtil#FIELD_UNSET}. 869 */ getRunAdBiddingLatencyInMs()870 private int getRunAdBiddingLatencyInMs() { 871 if (mRunAdBiddingStartTimestamp == 0L) { 872 return FIELD_UNSET; 873 } else if (mRunAdBiddingEndTimestamp == 0L) { 874 return (int) (mBiddingStageEndTimestamp - mRunAdBiddingStartTimestamp); 875 } 876 return (int) (mRunAdBiddingEndTimestamp - mRunAdBiddingStartTimestamp); 877 } 878 879 /** @return the total latency of ad bidding stage. */ getTotalAdBiddingStageLatencyInMs()880 private int getTotalAdBiddingStageLatencyInMs() { 881 if (mBiddingStageStartTimestamp == 0L) { 882 return FIELD_UNSET; 883 } 884 return (int) (mBiddingStageEndTimestamp - mBiddingStageStartTimestamp); 885 } 886 887 /** 888 * @return the latency in milliseconds of the persist-ad-selection process if started, otherwise 889 * the {@link AdServicesLoggerUtil#FIELD_UNSET}. 890 */ getPersistAdSelectionLatencyInMs()891 private int getPersistAdSelectionLatencyInMs() { 892 if (mPersistAdSelectionStartTimestamp == 0L) { 893 return FIELD_UNSET; 894 } else if (mPersistAdSelectionEndTimestamp == 0L) { 895 return (int) (getServiceElapsedTimestamp() - mPersistAdSelectionStartTimestamp); 896 } 897 return (int) (mPersistAdSelectionEndTimestamp - mPersistAdSelectionStartTimestamp); 898 } 899 getBinderLatencyInMs(long binderElapsedTimestamp)900 private int getBinderLatencyInMs(long binderElapsedTimestamp) { 901 return (int) (getStartElapsedTimestamp() - binderElapsedTimestamp) * 2; 902 } 903 } 904