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.server.wifi;
18 
19 import static com.android.server.wifi.proto.WifiStatsLog.WIFI_THREAD_TASK_EXECUTED;
20 
21 import android.annotation.NonNull;
22 import android.os.Bundle;
23 import android.os.Handler;
24 import android.os.HandlerThread;
25 import android.os.Looper;
26 import android.os.Message;
27 import android.os.SystemClock;
28 import android.os.Trace;
29 import android.util.LocalLog;
30 
31 import com.android.modules.utils.HandlerExecutor;
32 import com.android.server.wifi.proto.WifiStatsLog;
33 
34 import java.util.HashSet;
35 import java.util.Set;
36 
37 /**
38  * RunnerHandler tracks all the Runnable jobs posted to the handler for the running time and
39  * monitor if the running time exceeds the expected threshold.
40  *
41  */
42 public class RunnerHandler extends Handler {
43     private static final String TAG = "WifiThreadRunner";
44 
45     public static final String KEY_SIGNATURE = "KEY_RUNNER_HANDLER_SIGNATURE";
46     private static final String KEY_WHEN = "KEY_RUNNER_HANDLER_WHEN";
47     private static final int METRICS_THRESHOLD_MILLIS = 100;
48 
49     private final int mRunningTimeThresholdInMilliseconds;
50     private Set<String> mIgnoredClasses = new HashSet<>();
51     private Set<String> mIgnoredMethods = new HashSet<>();
52 
53     // TODO: b/246623192 Add Wifi metric for Runner state overruns.
54     private final LocalLog mLocalLog;
55 
56     /**
57      * The Runner handler Constructor
58      *
59      * @param looper looper for the handler
60      * @param threshold the running time threshold in milliseconds
61      */
RunnerHandler(Looper looper, int threshold, @NonNull LocalLog localLog)62     public RunnerHandler(Looper looper, int threshold, @NonNull LocalLog localLog) {
63         super(looper);
64         mRunningTimeThresholdInMilliseconds = threshold;
65         mLocalLog = localLog;
66         mIgnoredClasses.add(WifiThreadRunner.class.getName());
67         mIgnoredClasses.add(WifiThreadRunner.class.getName() + "$BlockingRunnable");
68         mIgnoredClasses.add(RunnerHandler.class.getName());
69         mIgnoredClasses.add(HandlerExecutor.class.getName());
70         mIgnoredClasses.add(Handler.class.getName());
71         mIgnoredClasses.add(HandlerThread.class.getName());
72         mIgnoredClasses.add(Looper.class.getName());
73         mIgnoredMethods.add("handleMessage");
74     }
75 
getSignature(StackTraceElement[] elements, Runnable callback)76     private String getSignature(StackTraceElement[] elements, Runnable callback) {
77         StringBuilder sb = new StringBuilder();
78         for (StackTraceElement e : elements) {
79             // Go through the stack elements to find out the caller who schedule the job.
80             // Ignore the stack frames generated with ignored classes and methods, until the stack
81             // frame where the runnable job is posted to the handler.
82             if (!mIgnoredClasses.contains(e.getClassName()) && !mIgnoredMethods.contains(
83                     e.getMethodName())) {
84                 String[] nameArr = e.getClassName().split("\\.", 5);
85                 final int len = nameArr.length;
86                 if (len > 0) {
87                     sb.append(nameArr[len - 1]).append("#").append(e.getMethodName());
88                     break;
89                 }
90             }
91             // The callback is the lambada function posted as Runnable#run function.
92             // If we can't identify the caller from the stack trace, then we will use the symbol
93             // of the lambada function as the signature of the caller.
94             if (HandlerThread.class.getName().equals(e.getClassName())) {
95                 sb.append(callback);
96                 break;
97             }
98         }
99         return sb.length() == 0 ? "<UNKNOWN>" : sb.toString();
100     }
101 
102     @Override
sendMessageAtTime(Message msg, long uptimeMillis)103     public boolean sendMessageAtTime(Message msg, long uptimeMillis) {
104         Bundle bundle = msg.getData();
105         if (bundle.getString(KEY_SIGNATURE) == null) {
106             String signature = getSignature(new Throwable("RunnerHandler:").getStackTrace(),
107                     msg.getCallback());
108             bundle.putString(KEY_SIGNATURE, signature);
109         }
110         return super.sendMessageAtTime(msg, uptimeMillis);
111     }
112 
113     @Override
dispatchMessage(@onNull Message msg)114     public void dispatchMessage(@NonNull Message msg) {
115         final Bundle bundle = msg.getData();
116         final String signature = bundle.getString(KEY_SIGNATURE);
117         if (signature != null) {
118             Trace.traceBegin(Trace.TRACE_TAG_NETWORK, signature);
119         }
120         // The message sent to front of the queue has when=0, get from the bundle in that case.
121         final long when = msg.getWhen() != 0 ? msg.getWhen() : bundle.getLong(KEY_WHEN);
122         final long start = SystemClock.uptimeMillis();
123         final long scheduleLatency = start - when;
124         super.dispatchMessage(msg);
125         if (signature != null) {
126             Trace.traceEnd(Trace.TRACE_TAG_NETWORK);
127         }
128         final long runTime = SystemClock.uptimeMillis() - start;
129         final String signatureToLog = signature != null ? signature : "unknown";
130         if (runTime > mRunningTimeThresholdInMilliseconds) {
131             mLocalLog.log(signatureToLog + " was running for " + runTime);
132         }
133         if (scheduleLatency > WifiThreadRunner.getScissorsTimeoutThreshold()) {
134             mLocalLog.log(signatureToLog + " schedule latency " + scheduleLatency + " ms");
135         }
136         if (runTime > METRICS_THRESHOLD_MILLIS || scheduleLatency > METRICS_THRESHOLD_MILLIS) {
137             WifiStatsLog.write(
138                     WIFI_THREAD_TASK_EXECUTED,
139                     (int) runTime,
140                     (int) scheduleLatency,
141                     signatureToLog);
142         }
143     }
144 
145     /**
146      * Use this helper function rather than directly calling Handler#postAtFrontOfQueue, which does
147      * not call sendMessageAtTime and set the signature. This function will set the signature
148      * before enqueueing the message to front of the queue.
149      * @param r runnable to be queued to the front
150      * @return true when success
151      */
postToFront(@onNull Runnable r)152     public final boolean postToFront(@NonNull Runnable r) {
153         Message msg = Message.obtain(this, r);
154         String signature = getSignature(new Throwable("RunnerHandler:").getStackTrace(),
155                 msg.getCallback());
156         Bundle bundle = msg.getData();
157         bundle.putString(KEY_SIGNATURE, signature);
158         bundle.putLong(KEY_WHEN, SystemClock.uptimeMillis());
159         return sendMessageAtFrontOfQueue(msg);
160     }
161 }
162