Merge "Add express logs for several JobScheduler events." into udc-dev (23fba5a6) · Commits · e / os / android_frameworks_base

apex/jobscheduler/service/java/com/android/server/job/JobConcurrencyManager.java

+9 −0

Original line number	Diff line number	Diff line
		@@ -62,6 +62,7 @@ import com.android.internal.app.IBatteryStats;
		import com.android.internal.app.procstats.ProcessStats;
		import com.android.internal.util.MemInfoReader;
		import com.android.internal.util.StatLogger;
		import com.android.modules.expresslog.Histogram;
		import com.android.server.AppSchedulingModuleThread;
		import com.android.server.LocalServices;
		import com.android.server.job.controllers.JobStatus;
		@@ -471,6 +472,13 @@ class JobConcurrencyManager {
		private final Consumer<PackageStats> mPackageStatsStagingCountClearer =
		PackageStats::resetStagedCount;

		private static final Histogram sConcurrencyHistogramLogger = new Histogram(
		"job_scheduler.value_hist_job_concurrency",
		// Create a histogram that expects values in the range [0, 99].
		// Include more buckets than MAX_CONCURRENCY_LIMIT to account for/identify the cases
		// where we may create additional slots for TOP-started EJs and UIJs
		new Histogram.UniformOptions(100, 0, 99));

		private final StatLogger mStatLogger = new StatLogger(new String[]{
		"assignJobsToContexts",
		"refreshSystemState",
		@@ -1433,6 +1441,7 @@ class JobConcurrencyManager {
		mService.mJobPackageTracker.noteConcurrency(mRunningJobs.size(),
		// TODO: log per type instead of only TOP
		mWorkCountTracker.getRunningJobCount(WORK_TYPE_TOP));
		sConcurrencyHistogramLogger.logSample(mActiveServices.size());
		}

		@GuardedBy("mLock")

apex/jobscheduler/service/java/com/android/server/job/JobNotificationCoordinator.java

+33 −4

Original line number	Diff line number	Diff line
		@@ -33,6 +33,7 @@ import android.util.SparseArrayMap;
		import android.util.SparseSetArray;

		import com.android.internal.annotations.GuardedBy;
		import com.android.modules.expresslog.Counter;
		import com.android.server.LocalServices;
		import com.android.server.job.controllers.JobStatus;
		import com.android.server.notification.NotificationManagerInternal;
		@@ -114,11 +115,39 @@ class JobNotificationCoordinator {
		@JobService.JobEndNotificationPolicy int jobEndNotificationPolicy) {
		validateNotification(packageName, callingUid, notification, jobEndNotificationPolicy);
		final JobStatus jobStatus = hostingContext.getRunningJobLocked();
		if (jobStatus == null) {
		Slog.wtfStack(TAG, "enqueueNotification called with no running job");
		return;
		}
		final NotificationDetails oldDetails = mNotificationDetails.get(hostingContext);
		if (oldDetails != null && oldDetails.notificationId != notificationId) {
		if (oldDetails == null) {
		if (jobStatus.startedAsUserInitiatedJob) {
		Counter.logIncrementWithUid(
		"job_scheduler.value_cntr_w_uid_initial_setNotification_call_required",
		jobStatus.getUid());
		} else {
		Counter.logIncrementWithUid(
		"job_scheduler.value_cntr_w_uid_initial_setNotification_call_optional",
		jobStatus.getUid());
		}
		} else {
		if (jobStatus.startedAsUserInitiatedJob) {
		Counter.logIncrementWithUid(
		"job_scheduler.value_cntr_w_uid_subsequent_setNotification_call_required",
		jobStatus.getUid());
		} else {
		Counter.logIncrementWithUid(
		"job_scheduler.value_cntr_w_uid_subsequent_setNotification_call_optional",
		jobStatus.getUid());
		}
		if (oldDetails.notificationId != notificationId) {
		// App is switching notification IDs. Remove association with the old one.
		removeNotificationAssociation(hostingContext, JobParameters.STOP_REASON_UNDEFINED,
		jobStatus);
		Counter.logIncrementWithUid(
		"job_scheduler.value_cntr_w_uid_setNotification_changed_notification_ids",
		jobStatus.getUid());
		}
		}
		final int userId = UserHandle.getUserId(callingUid);
		if (jobStatus != null && jobStatus.startedAsUserInitiatedJob) {

apex/jobscheduler/service/java/com/android/server/job/JobSchedulerService.java

+66 −0

Original line number	Diff line number	Diff line
		@@ -106,6 +106,8 @@ import com.android.internal.os.SomeArgs;
		import com.android.internal.util.ArrayUtils;
		import com.android.internal.util.DumpUtils;
		import com.android.internal.util.FrameworkStatsLog;
		import com.android.modules.expresslog.Counter;
		import com.android.modules.expresslog.Histogram;
		import com.android.server.AppSchedulingModuleThread;
		import com.android.server.AppStateTracker;
		import com.android.server.AppStateTrackerImpl;
		@@ -378,6 +380,28 @@ public class JobSchedulerService extends com.android.server.SystemService
		private final long[] mLastCancelledJobTimeElapsed =
		new long[DEBUG ? NUM_COMPLETED_JOB_HISTORY : 0];

		private static final Histogram sEnqueuedJwiHighWaterMarkLogger = new Histogram(
		"job_scheduler.value_hist_w_uid_enqueued_work_items_high_water_mark",
		new Histogram.ScaledRangeOptions(25, 0, 5, 1.4f));
		private static final Histogram sInitialJobEstimatedNetworkDownloadKBLogger = new Histogram(
		"job_scheduler.value_hist_initial_job_estimated_network_download_kilobytes",
		new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f));
		private static final Histogram sInitialJwiEstimatedNetworkDownloadKBLogger = new Histogram(
		"job_scheduler.value_hist_initial_jwi_estimated_network_download_kilobytes",
		new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f));
		private static final Histogram sInitialJobEstimatedNetworkUploadKBLogger = new Histogram(
		"job_scheduler.value_hist_initial_job_estimated_network_upload_kilobytes",
		new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f));
		private static final Histogram sInitialJwiEstimatedNetworkUploadKBLogger = new Histogram(
		"job_scheduler.value_hist_initial_jwi_estimated_network_upload_kilobytes",
		new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f));
		private static final Histogram sJobMinimumChunkKBLogger = new Histogram(
		"job_scheduler.value_hist_w_uid_job_minimum_chunk_kilobytes",
		new Histogram.ScaledRangeOptions(25, 0, 5 /* 5 KB */, 1.76f));
		private static final Histogram sJwiMinimumChunkKBLogger = new Histogram(
		"job_scheduler.value_hist_w_uid_jwi_minimum_chunk_kilobytes",
		new Histogram.ScaledRangeOptions(25, 0, 5 /* 5 KB */, 1.76f));

		/**
		* A mapping of which uids are currently in the foreground to their effective bias.
		*/
		@@ -1422,6 +1446,32 @@ public class JobSchedulerService extends com.android.server.SystemService
		return JobScheduler.RESULT_FAILURE;
		}

		if (job.getRequiredNetwork() != null) {
		sInitialJobEstimatedNetworkDownloadKBLogger.logSample(
		safelyScaleBytesToKBForHistogram(
		job.getEstimatedNetworkDownloadBytes()));
		sInitialJobEstimatedNetworkUploadKBLogger.logSample(
		safelyScaleBytesToKBForHistogram(job.getEstimatedNetworkUploadBytes()));
		sJobMinimumChunkKBLogger.logSampleWithUid(uId,
		safelyScaleBytesToKBForHistogram(job.getMinimumNetworkChunkBytes()));
		if (work != null) {
		sInitialJwiEstimatedNetworkDownloadKBLogger.logSample(
		safelyScaleBytesToKBForHistogram(
		work.getEstimatedNetworkDownloadBytes()));
		sInitialJwiEstimatedNetworkUploadKBLogger.logSample(
		safelyScaleBytesToKBForHistogram(
		work.getEstimatedNetworkUploadBytes()));
		sJwiMinimumChunkKBLogger.logSampleWithUid(uId,
		safelyScaleBytesToKBForHistogram(
		work.getMinimumNetworkChunkBytes()));
		}
		}

		if (work != null) {
		Counter.logIncrementWithUid(
		"job_scheduler.value_cntr_w_uid_job_work_items_enqueued", uId);
		}

		synchronized (mLock) {
		final JobStatus toCancel = mJobs.getJobByUidAndJobId(uId, namespace, job.getId());

		@@ -1451,6 +1501,7 @@ public class JobSchedulerService extends com.android.server.SystemService

		toCancel.enqueueWorkLocked(work);
		mJobs.touchJob(toCancel);
		sEnqueuedJwiHighWaterMarkLogger.logSampleWithUid(uId, toCancel.getWorkCount());

		// If any of work item is enqueued when the source is in the foreground,
		// exempt the entire job.
		@@ -1483,6 +1534,8 @@ public class JobSchedulerService extends com.android.server.SystemService
		if (packageName == null) {
		if (mJobs.countJobsForUid(uId) > MAX_JOBS_PER_APP) {
		Slog.w(TAG, "Too many jobs for uid " + uId);
		Counter.logIncrementWithUid(
		"job_scheduler.value_cntr_w_uid_max_scheduling_limit_hit", uId);
		throw new IllegalStateException("Apps may not schedule more than "
		+ MAX_JOBS_PER_APP + " distinct jobs");
		}
		@@ -1522,6 +1575,7 @@ public class JobSchedulerService extends com.android.server.SystemService
		if (work != null) {
		// If work has been supplied, enqueue it into the new job.
		jobStatus.enqueueWorkLocked(work);
		sEnqueuedJwiHighWaterMarkLogger.logSampleWithUid(uId, jobStatus.getWorkCount());
		}

		FrameworkStatsLog.write_non_chained(FrameworkStatsLog.SCHEDULED_JOB_STATE_CHANGED,
		@@ -3834,6 +3888,18 @@ public class JobSchedulerService extends com.android.server.SystemService
		return bucket;
		}

		static int safelyScaleBytesToKBForHistogram(long bytes) {
		long kilobytes = bytes / 1000;
		// Anything over Integer.MAX_VALUE or under Integer.MIN_VALUE isn't expected and will
		// be put into the overflow buckets.
		if (kilobytes > Integer.MAX_VALUE) {
		return Integer.MAX_VALUE;
		} else if (kilobytes < Integer.MIN_VALUE) {
		return Integer.MIN_VALUE;
		}
		return (int) kilobytes;
		}

		private class CloudProviderChangeListener implements
		StorageManagerInternal.CloudProviderChangeListener {

apex/jobscheduler/service/java/com/android/server/job/JobServiceContext.java

+106 −0

Original line number	Diff line number	Diff line
		@@ -20,6 +20,7 @@ import static android.app.job.JobInfo.getPriorityString;

		import static com.android.server.job.JobConcurrencyManager.WORK_TYPE_NONE;
		import static com.android.server.job.JobSchedulerService.sElapsedRealtimeClock;
		import static com.android.server.job.JobSchedulerService.safelyScaleBytesToKBForHistogram;

		import android.Manifest;
		import android.annotation.BytesLong;
		@@ -66,6 +67,8 @@ import com.android.internal.annotations.VisibleForTesting;
		import com.android.internal.app.IBatteryStats;
		import com.android.internal.os.TimeoutRecord;
		import com.android.internal.util.FrameworkStatsLog;
		import com.android.modules.expresslog.Counter;
		import com.android.modules.expresslog.Histogram;
		import com.android.server.EventLogTags;
		import com.android.server.LocalServices;
		import com.android.server.job.controllers.JobStatus;
		@@ -111,6 +114,22 @@ public final class JobServiceContext implements ServiceConnection {
		private static final long NOTIFICATION_TIMEOUT_MILLIS = 10_000L * Build.HW_TIMEOUT_MULTIPLIER;
		private static final long EXECUTION_DURATION_STAMP_PERIOD_MILLIS = 5 * 60_000L;

		private static final Histogram sEnqueuedJwiAtJobStart = new Histogram(
		"job_scheduler.value_hist_w_uid_enqueued_work_items_at_job_start",
		new Histogram.ScaledRangeOptions(20, 1, 3, 1.4f));
		private static final Histogram sTransferredNetworkDownloadKBHighWaterMarkLogger = new Histogram(
		"job_scheduler.value_hist_transferred_network_download_kilobytes_high_water_mark",
		new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f));
		private static final Histogram sTransferredNetworkUploadKBHighWaterMarkLogger = new Histogram(
		"job_scheduler.value_hist_transferred_network_upload_kilobytes_high_water_mark",
		new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f));
		private static final Histogram sUpdatedEstimatedNetworkDownloadKBLogger = new Histogram(
		"job_scheduler.value_hist_updated_estimated_network_download_kilobytes",
		new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f));
		private static final Histogram sUpdatedEstimatedNetworkUploadKBLogger = new Histogram(
		"job_scheduler.value_hist_updated_estimated_network_upload_kilobytes",
		new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f));

		private static final String[] VERB_STRINGS = {
		"VERB_BINDING", "VERB_STARTING", "VERB_EXECUTING", "VERB_STOPPING", "VERB_FINISHED"
		};
		@@ -480,6 +499,7 @@ public final class JobServiceContext implements ServiceConnection {
		job.getEstimatedNetworkUploadBytes(),
		job.getWorkCount(),
		ActivityManager.processStateAmToProto(mService.getUidProcState(job.getUid())));
		sEnqueuedJwiAtJobStart.logSampleWithUid(job.getUid(), job.getWorkCount());
		final String sourcePackage = job.getSourcePackageName();
		if (Trace.isTagEnabled(Trace.TRACE_TAG_SYSTEM_SERVER)) {
		final String componentPackage = job.getServiceComponent().getPackageName();
		@@ -816,6 +836,41 @@ public final class JobServiceContext implements ServiceConnection {
		if (!verifyCallerLocked(cb)) {
		return;
		}
		Counter.logIncrementWithUid(
		"job_scheduler.value_cntr_w_uid_estimated_network_bytes_updated",
		mRunningJob.getUid());
		sUpdatedEstimatedNetworkDownloadKBLogger.logSample(
		safelyScaleBytesToKBForHistogram(downloadBytes));
		sUpdatedEstimatedNetworkUploadKBLogger.logSample(
		safelyScaleBytesToKBForHistogram(uploadBytes));
		if (mEstimatedDownloadBytes != JobInfo.NETWORK_BYTES_UNKNOWN
		&& downloadBytes != JobInfo.NETWORK_BYTES_UNKNOWN) {
		if (mEstimatedDownloadBytes < downloadBytes) {
		Counter.logIncrementWithUid(
		"job_scheduler."
		+ "value_cntr_w_uid_estimated_network_download_bytes_increased",
		mRunningJob.getUid());
		} else if (mEstimatedDownloadBytes > downloadBytes) {
		Counter.logIncrementWithUid(
		"job_scheduler."
		+ "value_cntr_w_uid_estimated_network_download_bytes_decreased",
		mRunningJob.getUid());
		}
		}
		if (mEstimatedUploadBytes != JobInfo.NETWORK_BYTES_UNKNOWN
		&& uploadBytes != JobInfo.NETWORK_BYTES_UNKNOWN) {
		if (mEstimatedUploadBytes < uploadBytes) {
		Counter.logIncrementWithUid(
		"job_scheduler"
		+ ".value_cntr_w_uid_estimated_network_upload_bytes_increased",
		mRunningJob.getUid());
		} else if (mEstimatedUploadBytes > uploadBytes) {
		Counter.logIncrementWithUid(
		"job_scheduler"
		+ ".value_cntr_w_uid_estimated_network_upload_bytes_decreased",
		mRunningJob.getUid());
		}
		}
		mEstimatedDownloadBytes = downloadBytes;
		mEstimatedUploadBytes = uploadBytes;
		}
		@@ -828,6 +883,41 @@ public final class JobServiceContext implements ServiceConnection {
		if (!verifyCallerLocked(cb)) {
		return;
		}
		Counter.logIncrementWithUid(
		"job_scheduler.value_cntr_w_uid_transferred_network_bytes_updated",
		mRunningJob.getUid());
		sTransferredNetworkDownloadKBHighWaterMarkLogger.logSample(
		safelyScaleBytesToKBForHistogram(downloadBytes));
		sTransferredNetworkUploadKBHighWaterMarkLogger.logSample(
		safelyScaleBytesToKBForHistogram(uploadBytes));
		if (mTransferredDownloadBytes != JobInfo.NETWORK_BYTES_UNKNOWN
		&& downloadBytes != JobInfo.NETWORK_BYTES_UNKNOWN) {
		if (mTransferredDownloadBytes < downloadBytes) {
		Counter.logIncrementWithUid(
		"job_scheduler."
		+ "value_cntr_w_uid_transferred_network_download_bytes_increased",
		mRunningJob.getUid());
		} else if (mTransferredDownloadBytes > downloadBytes) {
		Counter.logIncrementWithUid(
		"job_scheduler."
		+ "value_cntr_w_uid_transferred_network_download_bytes_decreased",
		mRunningJob.getUid());
		}
		}
		if (mTransferredUploadBytes != JobInfo.NETWORK_BYTES_UNKNOWN
		&& uploadBytes != JobInfo.NETWORK_BYTES_UNKNOWN) {
		if (mTransferredUploadBytes < uploadBytes) {
		Counter.logIncrementWithUid(
		"job_scheduler."
		+ "value_cntr_w_uid_transferred_network_upload_bytes_increased",
		mRunningJob.getUid());
		} else if (mTransferredUploadBytes > uploadBytes) {
		Counter.logIncrementWithUid(
		"job_scheduler."
		+ "value_cntr_w_uid_transferred_network_upload_bytes_decreased",
		mRunningJob.getUid());
		}
		}
		mTransferredDownloadBytes = downloadBytes;
		mTransferredUploadBytes = uploadBytes;
		}
		@@ -898,6 +988,11 @@ public final class JobServiceContext implements ServiceConnection {
		// Use that as the stop reason for logging/debugging purposes.
		mParams.setStopReason(
		mDeathMarkStopReason, mDeathMarkInternalStopReason, mDeathMarkDebugReason);
		} else if (mRunningJob != null) {
		Counter.logIncrementWithUid(
		"job_scheduler.value_cntr_w_uid_unexpected_service_disconnects",
		// Use the calling UID since that's the one this context was connected to.
		mRunningJob.getUid());
		}
		closeAndCleanupJobLocked(true /* needsReschedule */, "unexpectedly disconnected");
		}
		@@ -1224,6 +1319,8 @@ public final class JobServiceContext implements ServiceConnection {
		switch (mVerb) {
		case VERB_BINDING:
		onSlowAppResponseLocked(/* reschedule / false, / updateStopReasons */ true,
		/* texCounterMetricId */
		"job_scheduler.value_cntr_w_uid_slow_app_response_binding",
		/* debugReason */ "timed out while binding",
		/* anrMessage */ "Timed out while trying to bind",
		CompatChanges.isChangeEnabled(ANR_PRE_UDC_APIS_ON_SLOW_RESPONSES,
		@@ -1234,6 +1331,8 @@ public final class JobServiceContext implements ServiceConnection {
		// know what happened so let's log it and notify the JobScheduler
		// FINISHED/NO-RETRY.
		onSlowAppResponseLocked(/* reschedule / false, / updateStopReasons */ true,
		/* texCounterMetricId */
		"job_scheduler.value_cntr_w_uid_slow_app_response_onStartJob",
		/* debugReason */ "timed out while starting",
		/* anrMessage */ "No response to onStartJob",
		CompatChanges.isChangeEnabled(ANR_PRE_UDC_APIS_ON_SLOW_RESPONSES,
		@@ -1244,6 +1343,8 @@ public final class JobServiceContext implements ServiceConnection {
		// Don't update the stop reasons since we were already stopping the job for some
		// other reason.
		onSlowAppResponseLocked(/* reschedule / true, / updateStopReasons */ false,
		/* texCounterMetricId */
		"job_scheduler.value_cntr_w_uid_slow_app_response_onStopJob",
		/* debugReason */ "timed out while stopping",
		/* anrMessage */ "No response to onStopJob",
		CompatChanges.isChangeEnabled(ANR_PRE_UDC_APIS_ON_SLOW_RESPONSES,
		@@ -1299,6 +1400,8 @@ public final class JobServiceContext implements ServiceConnection {
		}
		} else if (mAwaitingNotification) {
		onSlowAppResponseLocked(/* reschedule / true, / updateStopReasons */ true,
		/* texCounterMetricId */
		"job_scheduler.value_cntr_w_uid_slow_app_response_setNotification",
		/* debugReason */ "timed out while stopping",
		/* anrMessage */ "required notification not provided",
		/* triggerAnr */ true);
		@@ -1348,8 +1451,11 @@ public final class JobServiceContext implements ServiceConnection {

		@GuardedBy("mLock")
		private void onSlowAppResponseLocked(boolean reschedule, boolean updateStopReasons,
		@NonNull String texCounterMetricId,
		@NonNull String debugReason, @NonNull String anrMessage, boolean triggerAnr) {
		Slog.w(TAG, anrMessage + " for " + getRunningJobNameLocked());
		// Use the calling UID since that's the one this context was connected to.
		Counter.logIncrementWithUid(texCounterMetricId, mRunningJob.getUid());
		if (updateStopReasons) {
		mParams.setStopReason(
		JobParameters.STOP_REASON_UNDEFINED,

apex/jobscheduler/service/java/com/android/server/job/controllers/TimeController.java

+1 −0

Original line number	Diff line number	Diff line
		@@ -90,6 +90,7 @@ public final class TimeController extends StateController {
		final long nowElapsedMillis = sElapsedRealtimeClock.millis();
		if (job.hasDeadlineConstraint() && evaluateDeadlineConstraint(job, nowElapsedMillis)) {
		// We're intentionally excluding jobs whose deadlines have passed
		// from the job_scheduler.value_job_scheduler_job_deadline_expired_counter count
		// (mostly like deadlines of 0) when the job was scheduled.
		return;
		} else if (job.hasTimingDelayConstraint() && evaluateTimingDelayConstraint(job,