1 /*
2  * Copyright (C) 2018 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 package android.device.collectors;
17 
18 import android.content.Context;
19 import android.device.collectors.annotations.OptionClass;
20 import android.os.Bundle;
21 import android.os.PowerManager;
22 import android.os.PowerManager.WakeLock;
23 import android.os.SystemClock;
24 import android.util.Log;
25 import androidx.annotation.VisibleForTesting;
26 import com.android.helpers.PerfettoHelper;
27 
28 import java.io.IOException;
29 import java.nio.file.Path;
30 import java.nio.file.Paths;
31 import java.util.HashMap;
32 import java.util.Map;
33 import java.util.UUID;
34 import java.util.function.Supplier;
35 import org.junit.runner.Description;
36 import org.junit.runner.Result;
37 import org.junit.runner.notification.Failure;
38 
39 /**
40  * A {@link PerfettoListener} that captures the perfetto trace during each test method
41  * and save the perfetto trace files under
42  * <root_folder>/<test_display_name>/PerfettoListener/<test_display_name>-<invocation_count>.pb
43  */
44 @OptionClass(alias = "perfetto-collector")
45 public class PerfettoListener extends BaseMetricListener {
46 
47     // Default perfetto config file name.
48     private static final String DEFAULT_CONFIG_FILE = "trace_config.pb";
49     // Default wait time before stopping the perfetto trace.
50     private static final String DEFAULT_WAIT_TIME_MSECS = "3000";
51     // Option to pass the folder name which contains the perfetto trace config file.
52     private static final String PERFETTO_CONFIG_ROOT_DIR_ARG = "perfetto_config_root_dir";
53     // Default folder name to look for the perfetto config file.
54     private static final String DEFAULT_PERFETTO_CONFIG_ROOT_DIR = "/data/misc/perfetto-traces/";
55     // Default output folder to store the perfetto output traces.
56     private static final String DEFAULT_OUTPUT_ROOT = "/sdcard/test_results";
57     // Argument to indicate the perfetto config file is text proto file.
58     public static final String PERFETTO_CONFIG_TEXT_PROTO = "perfetto_config_text_proto";
59     // Argument to get custom config file name for collecting the trace.
60     private static final String PERFETTO_CONFIG_FILE_ARG = "perfetto_config_file";
61     // Argument to get custom time in millisecs to wait before dumping the trace.
62     // This has to be atleast the dump interval time set in the trace config file
63     // or greater than that. Otherwise we will miss trace information from the test.
64     private static final String PERFETTO_WAIT_TIME_ARG = "perfetto_wait_time_ms";
65     // Destination directory to save the trace results.
66     private static final String TEST_OUTPUT_ROOT = "test_output_root";
67     // Perfetto file path key.
68     private static final String PERFETTO_FILE_PATH = "perfetto_file_path";
69     // Collect per run if it is set to true otherwise collect per test.
70     public static final String COLLECT_PER_RUN = "per_run";
71     public static final String PERFETTO_PREFIX = "perfetto_";
72     // Skip failure metrics collection if this flag is set to true.
73     public static final String SKIP_TEST_FAILURE_METRICS = "skip_test_failure_metrics";
74     // Argument to get custom time in millisecs to wait before starting the
75     // perfetto trace.
76     public static final String PERFETTO_START_WAIT_TIME_ARG = "perfetto_start_wait_time_ms";
77     // Default wait time before starting the perfetto trace.
78     public static final String DEFAULT_START_WAIT_TIME_MSECS = "3000";
79     // Regular expression pattern to identify multiple spaces.
80     public static final String SPACES_PATTERN = "\\s+";
81     // Space replacement value
82     public static final String REPLACEMENT_CHAR = "#";
83 
84     private final WakeLockContext mWakeLockContext;
85     private final Supplier<WakeLock> mWakelockSupplier;
86     private final WakeLockAcquirer mWakeLockAcquirer;
87     private final WakeLockReleaser mWakeLockReleaser;
88 
89     private String mConfigRootDir;
90     // Trace config file name to use while collecting the trace which is defaulted to
91     // trace_config.pb. It can be changed via the perfetto_config_file arg.
92     private String mConfigFileName;
93     // Wait time can be customized based on the dump interval set in the trace config.
94     private long mWaitTimeInMs;
95     // Wait time can be customized based on how much time to wait before starting the
96     // trace.
97     private long mWaitStartTimeInMs;
98     // Perfetto traces collected during the test will be saved under this root folder.
99     private String mTestOutputRoot;
100     // Store the method name and invocation count to create unique file name for each trace.
101     private Map<String, Integer> mTestIdInvocationCount = new HashMap<>();
102     private boolean mPerfettoStartSuccess = false;
103     private boolean mIsConfigTextProto = false;
104     private boolean mIsCollectPerRun;
105     private boolean mSkipTestFailureMetrics;
106     private boolean mIsTestFailed = false;
107 
108     private PerfettoHelper mPerfettoHelper = new PerfettoHelper();
109 
110     // For USB disconnected cases you may want this option to be true. This option makes sure
111     // the device does not go to sleep while collecting.
112     @VisibleForTesting
113     static final String HOLD_WAKELOCK_WHILE_COLLECTING = "hold_wakelock_while_collecting";
114 
115     private boolean mHoldWakelockWhileCollecting;
116 
PerfettoListener()117     public PerfettoListener() {
118         super();
119         mWakeLockContext = this::runWithWakeLock;
120         mWakelockSupplier = this::getWakeLock;
121         mWakeLockAcquirer = this::acquireWakelock;
122         mWakeLockReleaser = this::releaseWakelock;
123     }
124 
125     /**
126      * Constructor to simulate receiving the instrumentation arguments. Should not be used except
127      * for testing.
128      */
129     @VisibleForTesting
PerfettoListener( Bundle args, PerfettoHelper helper, Map invocationMap, WakeLockContext wakeLockContext, Supplier<WakeLock> wakelockSupplier, WakeLockAcquirer wakeLockAcquirer, WakeLockReleaser wakeLockReleaser)130     PerfettoListener(
131             Bundle args,
132             PerfettoHelper helper,
133             Map invocationMap,
134             WakeLockContext wakeLockContext,
135             Supplier<WakeLock> wakelockSupplier,
136             WakeLockAcquirer wakeLockAcquirer,
137             WakeLockReleaser wakeLockReleaser) {
138         super(args);
139         mPerfettoHelper = helper;
140         mTestIdInvocationCount = invocationMap;
141         mWakeLockContext = wakeLockContext;
142         mWakeLockAcquirer = wakeLockAcquirer;
143         mWakeLockReleaser = wakeLockReleaser;
144         mWakelockSupplier = wakelockSupplier;
145     }
146 
147     @Override
onTestRunStart(DataRecord runData, Description description)148     public void onTestRunStart(DataRecord runData, Description description) {
149         if (!mIsCollectPerRun) {
150             return;
151         }
152 
153         Runnable task =
154                 () -> {
155                     Log.i(getTag(), "Starting perfetto before test run started.");
156                     startPerfettoTracing();
157                 };
158 
159         if (mHoldWakelockWhileCollecting) {
160             Log.d(getTag(), "Holding a wakelock at onTestRunSTart.");
161             mWakeLockContext.run(task);
162         } else {
163             task.run();
164         }
165     }
166 
167     @Override
onTestStart(DataRecord testData, Description description)168     public void onTestStart(DataRecord testData, Description description) {
169         mIsTestFailed = false;
170         if (mIsCollectPerRun) {
171             return;
172         }
173 
174         Runnable task =
175                 () -> {
176                     mTestIdInvocationCount.compute(
177                             getTestFileName(description),
178                             (key, value) -> (value == null) ? 1 : value + 1);
179                     Log.i(getTag(), "Starting perfetto before test started.");
180                     startPerfettoTracing();
181                 };
182 
183         if (mHoldWakelockWhileCollecting) {
184             Log.d(getTag(), "Holding a wakelock at onTestStart.");
185             mWakeLockContext.run(task);
186         } else {
187             task.run();
188         }
189     }
190 
191     @Override
onTestFail(DataRecord testData, Description description, Failure failure)192     public void onTestFail(DataRecord testData, Description description, Failure failure) {
193         mIsTestFailed = true;
194     }
195 
196     @Override
onTestEnd(DataRecord testData, Description description)197     public void onTestEnd(DataRecord testData, Description description) {
198         if (mIsCollectPerRun) {
199             return;
200         }
201 
202         if (!mPerfettoStartSuccess) {
203             Log.i(
204                     getTag(),
205                     "Skipping perfetto stop attempt onTestEnd because perfetto did not "
206                             + "start successfully.");
207             return;
208         }
209 
210         Runnable task = null;
211         if (mSkipTestFailureMetrics && mIsTestFailed) {
212             Log.i(getTag(), "Skipping the metric collection due to test failure.");
213             // Stop the existing perfetto trace collection.
214             try {
215                 if (!mPerfettoHelper.stopPerfetto()) {
216                     Log.e(getTag(), "Failed to stop the perfetto process.");
217                 }
218             } catch (IOException e) {
219                 Log.e(getTag(), "Failed to stop the perfetto.", e);
220             }
221         } else {
222             task =
223                     () -> {
224                         Log.i(getTag(), "Stopping perfetto after test ended.");
225                         // Construct test output directory in the below format
226                         // <root_folder>/<test_name>/PerfettoListener/<test_name>-<count>.pb
227                         Path path =
228                                 Paths.get(
229                                         mTestOutputRoot,
230                                         getTestFileName(description),
231                                         this.getClass().getSimpleName(),
232                                         String.format(
233                                                 "%s%s-%d.pb",
234                                                 PERFETTO_PREFIX,
235                                                 getTestFileName(description),
236                                                 mTestIdInvocationCount.get(
237                                                         getTestFileName(description))));
238                         stopPerfettoTracing(path, testData);
239                     };
240             if (mHoldWakelockWhileCollecting) {
241                 Log.d(getTag(), "Holding a wakelock at onTestEnd.");
242                 mWakeLockContext.run(task);
243             } else {
244                 task.run();
245             }
246         }
247     }
248 
249     @Override
onTestRunEnd(DataRecord runData, Result result)250     public void onTestRunEnd(DataRecord runData, Result result) {
251         if (!mIsCollectPerRun) {
252             return;
253         }
254         if (!mPerfettoStartSuccess) {
255             Log.i(
256                     getTag(),
257                     "Skipping perfetto stop attempt because perfetto did not "
258                             + "start successfully.");
259             return;
260         }
261 
262         Runnable task =
263                 () -> {
264                     Log.i(getTag(), "Stopping perfetto after test run ended.");
265                     // Construct test output directory in the below format
266                     // <root_folder>/PerfettoListener/<randomUUID>.pb
267                     Path path =
268                             Paths.get(
269                                     mTestOutputRoot,
270                                     this.getClass().getSimpleName(),
271                                     String.format(
272                                             "%s%d.pb",
273                                             PERFETTO_PREFIX, UUID.randomUUID().hashCode()));
274                     stopPerfettoTracing(path, runData);
275                 };
276 
277         if (mHoldWakelockWhileCollecting) {
278             Log.d(getTag(), "Holding a wakelock at onTestRunEnd.");
279             mWakeLockContext.run(task);
280         } else {
281             task.run();
282         }
283     }
284 
285     @Override
setupAdditionalArgs()286     public void setupAdditionalArgs() {
287         Bundle args = getArgsBundle();
288 
289         // Whether to collect the for the entire test run or per test.
290         mIsCollectPerRun = Boolean.parseBoolean(args.getString(COLLECT_PER_RUN));
291 
292         // Root directory path containing the perfetto config file.
293         mConfigRootDir =
294                 args.getString(PERFETTO_CONFIG_ROOT_DIR_ARG, DEFAULT_PERFETTO_CONFIG_ROOT_DIR);
295         if (!mConfigRootDir.endsWith("/")) {
296             mConfigRootDir = mConfigRootDir.concat("/");
297         }
298         mPerfettoHelper.setPerfettoConfigRootDir(mConfigRootDir);
299 
300         // Whether the config is text proto or not. By default set to false.
301         mIsConfigTextProto = Boolean.parseBoolean(args.getString(PERFETTO_CONFIG_TEXT_PROTO));
302 
303         // Perfetto config file has to be under /data/misc/perfetto-traces/
304         // defaulted to trace_config.pb is perfetto_config_file is not passed.
305         mConfigFileName = args.getString(PERFETTO_CONFIG_FILE_ARG, DEFAULT_CONFIG_FILE);
306 
307         // Whether to hold wakelocks on all Prefetto tracing functions. You may want to enable
308         // this if your device is not USB connected. This option prevents the device from
309         // going into suspend mode while this listener is running intensive tasks.
310         mHoldWakelockWhileCollecting =
311                 Boolean.parseBoolean(args.getString(HOLD_WAKELOCK_WHILE_COLLECTING));
312 
313         // Wait time before stopping the perfetto trace collection after the test
314         // is completed. Defaulted to 3000 msecs if perfetto_wait_time_ms is not passed.
315         // TODO: b/118122395 for parsing failures.
316         mWaitTimeInMs =
317                 Long.parseLong(args.getString(PERFETTO_WAIT_TIME_ARG, DEFAULT_WAIT_TIME_MSECS));
318 
319         // TODO: b/165344369 to avoid wait time before starting the perfetto trace.
320         mWaitStartTimeInMs =
321                 Long.parseLong(
322                         args.getString(
323                                 PERFETTO_START_WAIT_TIME_ARG, DEFAULT_START_WAIT_TIME_MSECS));
324 
325         // Destination folder in the device to save all the trace files.
326         // Defaulted to /sdcard/test_results if test_output_root is not passed.
327         mTestOutputRoot = args.getString(TEST_OUTPUT_ROOT, DEFAULT_OUTPUT_ROOT);
328 
329         // By default this flag is set to false to collect the metrics on test failure.
330         mSkipTestFailureMetrics = "true".equals(args.getString(SKIP_TEST_FAILURE_METRICS));
331     }
332 
333     @VisibleForTesting
runWithWakeLock(Runnable runnable)334     void runWithWakeLock(Runnable runnable) {
335         WakeLock wakelock = null;
336         try {
337             wakelock = mWakelockSupplier.get();
338             mWakeLockAcquirer.acquire(wakelock);
339             runnable.run();
340         } finally {
341             mWakeLockReleaser.release(wakelock);
342         }
343     }
344 
345     interface WakeLockContext {
run(Runnable runnable)346         void run(Runnable runnable);
347     }
348 
349     interface WakeLockAcquirer {
acquire(WakeLock wakelock)350         void acquire(WakeLock wakelock);
351     }
352 
353     interface WakeLockReleaser {
release(WakeLock wakelock)354         void release(WakeLock wakelock);
355     }
356 
357     @VisibleForTesting
acquireWakelock(WakeLock wakelock)358     public void acquireWakelock(WakeLock wakelock) {
359         if (wakelock != null) {
360             Log.d(getTag(), "wakelock.isHeld: " + wakelock.isHeld());
361             Log.d(getTag(), "acquiring wakelock.");
362             wakelock.acquire();
363             Log.d(getTag(), "wakelock acquired.");
364             Log.d(getTag(), "wakelock.isHeld: " + wakelock.isHeld());
365         }
366     }
367 
368     @VisibleForTesting
releaseWakelock(WakeLock wakelock)369     public void releaseWakelock(WakeLock wakelock) {
370         if (wakelock != null) {
371             Log.d(getTag(), "wakelock.isHeld: " + wakelock.isHeld());
372             Log.d(getTag(), "releasing wakelock.");
373             wakelock.release();
374             Log.d(getTag(), "wakelock released.");
375             Log.d(getTag(), "wakelock.isHeld: " + wakelock.isHeld());
376         }
377     }
378 
getWakeLock()379     private WakeLock getWakeLock() {
380         PowerManager pm =
381                 (PowerManager)
382                         getInstrumentation().getContext().getSystemService(Context.POWER_SERVICE);
383 
384         return pm.newWakeLock(PowerManager.PARTIAL_WAKE_LOCK, PerfettoListener.class.getName());
385     }
386 
387     /**
388      * Start perfetto tracing using the given config file.
389      */
startPerfettoTracing()390     private void startPerfettoTracing() {
391         SystemClock.sleep(mWaitStartTimeInMs);
392         mPerfettoStartSuccess = mPerfettoHelper.startCollecting(mConfigFileName,
393                 mIsConfigTextProto);
394         if (!mPerfettoStartSuccess) {
395             Log.e(getTag(), "Perfetto did not start successfully.");
396         }
397     }
398 
399     /**
400      * Stop perfetto tracing and dumping the collected trace file in given path and updating the
401      * record with the path to the trace file.
402      */
stopPerfettoTracing(Path path, DataRecord record)403     private void stopPerfettoTracing(Path path, DataRecord record) {
404         if (!mPerfettoHelper.stopCollecting(mWaitTimeInMs, path.toString())) {
405             Log.e(getTag(), "Failed to collect the perfetto output.");
406         } else {
407             record.addStringMetric(PERFETTO_FILE_PATH, path.toString());
408         }
409     }
410 
411     /**
412      * Returns the packagename.classname_methodname which has no spaces and used to create file
413      * names.
414      */
getTestFileName(Description description)415     public static String getTestFileName(Description description) {
416         return String.format("%s_%s",
417                 description.getClassName().replaceAll(SPACES_PATTERN, REPLACEMENT_CHAR).trim(),
418                 description.getMethodName().replaceAll(SPACES_PATTERN, REPLACEMENT_CHAR).trim());
419     }
420 }
421