/* * Copyright (C) 2013 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ package com.android.uiautomator.platform; import android.os.Environment; import android.util.Log; import java.util.Arrays; import java.util.List; import java.util.ArrayList; import java.io.BufferedReader; import java.io.File; import java.io.FileWriter; import java.io.BufferedWriter; import java.io.InputStreamReader; import java.io.IOException; import java.lang.Math; /* * Tools to measure jankiness through SurfaceFlinger */ public class SurfaceFlingerHelper { private static String TAG = "SurfaceFlingerHelper"; private static int BUFFER_SIZE = 128; private static int BUFFER_NUMBER = 3; private static String CLEAR_BUFFER_CMD = "dumpsys SurfaceFlinger --latency-clear"; private static String FRAME_LATENCY_CMD = "dumpsys SurfaceFlinger --latency"; private static final String RAW_DATA_DIR = "UiJankinessRawData"; private static final String LOCAL_TMP_DIR = "/data/local/tmp/"; /* If the latency between two frames is greater than this number, it it treated as a pause * not a jankiness */ private static final int PAUSE_LATENCY = 20; /* An array list which includes the raw buffer information from frame latency tool */ private static List> mFrameBufferData = new ArrayList>(BUFFER_SIZE); /* Record the refresh period returned from driver */ private static long mRefreshPeriod = -1; /* Record the size of frame latency */ private static int mFrameLatencySampleSize = 0; /* An integer array which includes delta vsync */ private static long[] mDeltaVsync = new long[BUFFER_SIZE]; /* Integer array for delta of delta vsync */ private static long[] mDelta2Vsync = new long[BUFFER_SIZE]; /* the maximum delta vsync number */ private static long mMaxDeltaVsync; /* Normalized data */ private static double[] mNormalizedDelta2Vsync = new double[BUFFER_SIZE]; private static int[] mRoundNormalizedDelta2Vsync = new int[BUFFER_SIZE]; // Symbol of unfinished frame time */ public static final String PENDING_FENCE_TIME = new Long(Long.MAX_VALUE).toString(); /** * Run clear buffer command and clear the saved frame buffer results * * @param windowName the window name that the buffer will be cleared */ public static void clearBuffer(String windowName) { // clear results if (mFrameBufferData != null) { mFrameBufferData.clear(); } Arrays.fill(mDeltaVsync, -1); Arrays.fill(mDelta2Vsync, -1); Arrays.fill(mNormalizedDelta2Vsync, -1.0); Arrays.fill(mRoundNormalizedDelta2Vsync, -1); mRefreshPeriod = -1; mFrameLatencySampleSize = 0; mMaxDeltaVsync = 0; Process p = null; BufferedReader resultReader = null; String command = CLEAR_BUFFER_CMD; if (windowName != null) { command = String.format("%s %s", CLEAR_BUFFER_CMD, windowName); } try { p = Runtime.getRuntime().exec(command); int status = p.waitFor(); if (status != 0) { Log.e(TAG, String.format("Run shell command: %s, status: %s", command, status)); } } catch (IOException e) { Log.e(TAG, "// Exception from command " + command + ":", e); } catch (InterruptedException e) { Log.e(TAG, "// Interrupted while waiting for the command to finish. ", e); } finally { try { if (resultReader != null) { resultReader.close(); } if (p != null) { p.destroy(); } } catch (IOException e) { Log.e(TAG, "exception " + e); } } } /** * Run frame latency command without ignoring pending fence time * * @param windowName the window name which SurfaceFlinger will acquire frame time for */ public static boolean dumpFrameLatency(String windowName) { return dumpFrameLatency(windowName, false); } /** * Run frame latency command to get frame time * * @param windowName the window name which SurfaceFlinger will get frame time for * @param ignorePendingFenceTime flag to process frames with pending fence time * set true to ignore pending fence time * set false to fail the test if pending fence time is not allowed */ public static boolean dumpFrameLatency(String windowName, boolean ignorePendingFenceTime) { Process p = null; BufferedReader resultReader = null; String command = FRAME_LATENCY_CMD; if (windowName != null) { command = String.format("%s %s", FRAME_LATENCY_CMD, windowName); } log("dump frame latency command: " + command); try { p = Runtime.getRuntime().exec(command); int status = p.waitFor(); if (status != 0) { Log.e(TAG, String.format("Run shell command: %s, status: %s",command, status)); } resultReader = new BufferedReader(new InputStreamReader(p.getInputStream())); String line = resultReader.readLine(); mRefreshPeriod = Long.parseLong(line.trim()); log("reading refresh period: " + mRefreshPeriod); if (mRefreshPeriod < 0) { return false; } boolean dataInvalidFlag = false; while((line = resultReader.readLine()) != null) { // remove lines which are empty if (line.trim().isEmpty()) { break; } String[] bufferValues = line.split("\\s+"); if (bufferValues[0].trim().compareTo("0") == 0) { continue; } else if (bufferValues[1].trim().compareTo(PENDING_FENCE_TIME) == 0 ) { if (ignorePendingFenceTime) { log("ignore pending fence time"); dataInvalidFlag = true; } else { log("the data contains unfinished frame time, please allow the animation" + " to finish in the test before calling dumpFrameLatency."); return false; } } // store raw data which could have both valid and invalid data List delayArray = Arrays.asList(bufferValues); mFrameBufferData.add(delayArray); if (!dataInvalidFlag) { // only count frames which have valid time ++mFrameLatencySampleSize; } } log("frame latency sample size: " + mFrameLatencySampleSize); } catch (InterruptedException e) { Log.e(TAG, "// Exception from command " + command + ":", e); } catch (IOException e) { Log.e(TAG, "Open file error: ", e); return false; } finally { try { if (resultReader != null) { resultReader.close(); } if (p != null) { p.destroy(); } } catch (IOException e) { Log.e(TAG, "io exception: ", e); } } return true; } public static int getDataSampleSize() { return mFrameLatencySampleSize; } public static long getRefreshPeriod() { if (mRefreshPeriod < 0) { // Haven't dump the frame latency yet log("Run command \"" + FRAME_LATENCY_CMD + " \" before retrieving the refresh period"); } return mRefreshPeriod; } public static String getFrameBufferData() { if (mFrameBufferData.get(0) == null) { log("Run command \"" + FRAME_LATENCY_CMD + " \" before retrieving frame buffer data"); return null; } String rawData = String.format("%d\n", mRefreshPeriod); List tempList = new ArrayList(BUFFER_NUMBER); for (int i = 0; i < mFrameBufferData.size(); i++) { tempList = mFrameBufferData.get(i); for (int j = 0; j < BUFFER_NUMBER; j++) { rawData += String.format("%s", tempList.get(j)); if (j < BUFFER_NUMBER - 1) { rawData += "\t"; } else { rawData += "\n"; } } } return rawData; } /** * Calculate delta(vsync) * @return */ public static long[] getDeltaVsync() { if (mRefreshPeriod < 0) { log("Run command \"" + FRAME_LATENCY_CMD + " \" before retrieving frame latency"); return null; } if (mDeltaVsync[0] < 0 ) { // keep a record of the max DeltaVsync mMaxDeltaVsync = 0; // get the first frame vsync time long preVsyncTime = Long.parseLong(mFrameBufferData.get(0).get(1)); for (int i = 0; i < mFrameLatencySampleSize - 1; i++) { long curVsyncTime = Long.parseLong(mFrameBufferData.get(i + 1).get(1)); mDeltaVsync[i] = curVsyncTime - preVsyncTime; preVsyncTime = curVsyncTime; if (mMaxDeltaVsync < mDeltaVsync[i]) { mMaxDeltaVsync = mDeltaVsync[i]; } } } return mDeltaVsync; } /** * Calculate difference between delta vsync * @return */ public static long[] getDelta2Vsync() { if (mRefreshPeriod < 0) { log("Run command \"" + FRAME_LATENCY_CMD + " \" before retrieving frame latency"); return null; } if (mDeltaVsync[0] < 0) { getDeltaVsync(); } if (mDelta2Vsync[0] < 0) { int numDeltaVsync = mFrameLatencySampleSize - 1; for (int i = 0; i < numDeltaVsync - 1; i++) { mDelta2Vsync[i] = mDeltaVsync[i + 1] - mDeltaVsync[i]; } } return mDelta2Vsync; } /** * normalized delta(delta(vsync)) by refresh period * @return */ public static double[] getNormalizedDelta2Vsync() { if (mRefreshPeriod < 0) { log("Run command \"" + FRAME_LATENCY_CMD + " \" before retrieving frame latency"); return null; } if (mDelta2Vsync[0] < 0) { getDelta2Vsync(); } if (mNormalizedDelta2Vsync[0] < 0) { for (int i = 0; i < mFrameLatencySampleSize - 2; i++) { mNormalizedDelta2Vsync[i] = (double)mDelta2Vsync[i] /mRefreshPeriod; } } return mNormalizedDelta2Vsync; } public static int[] getRoundNormalizedDelta2Vsync() { if (mRefreshPeriod < 0) { log("Run command \"" + FRAME_LATENCY_CMD + " \" for number of jankiness."); return null; } if (mNormalizedDelta2Vsync[0] < 0) { getNormalizedDelta2Vsync(); } for (int i = 0; i < mFrameLatencySampleSize - 2; i++) { int value = (int)Math.round(Math.max(mNormalizedDelta2Vsync[i], 0.0)); mRoundNormalizedDelta2Vsync[i] = value; } return mRoundNormalizedDelta2Vsync; } /* * Get number of jankiness using Vsync time difference */ public static int getVsyncJankiness() { if (mRefreshPeriod < 0) { log("Run command \"" + FRAME_LATENCY_CMD + " \" for number of jankiness."); return -1; } if (mRoundNormalizedDelta2Vsync[0] < 0) { getRoundNormalizedDelta2Vsync(); } int numberJankiness = 0; for (int i = 0; i < mFrameLatencySampleSize - 2; i++) { int value = mRoundNormalizedDelta2Vsync[i]; // ignore the latency which is too long if (value > 0 && value < PAUSE_LATENCY) { numberJankiness++; } } return numberJankiness; } /* Track the maximum delta which shows the accumulating time * before animation starts */ public static int getMaxDeltaVsync() { return Math.round((float)mMaxDeltaVsync /mRefreshPeriod); } /** * Calculate frame rate * @return */ public static double getFrameRate() { if (mRefreshPeriod < 0) { log("Run command \"" + FRAME_LATENCY_CMD + " \" before calcuating average frame rate"); return -1.0; } if (mFrameBufferData.get(0) == null) { log("Run command \"" + FRAME_LATENCY_CMD + " \" before retrieving frame buffer data"); return -1.0; } long startTime = Long.parseLong(mFrameBufferData.get(0).get(1)); long endTime = Long.parseLong(mFrameBufferData.get(mFrameLatencySampleSize - 1).get(1)); long totalDuration = endTime - startTime; return (double)((mFrameLatencySampleSize - 1) * Math.pow(10, 9))/totalDuration; } /** * Print raw data and processed results into file * @param fileName * @param index */ public static void printData(String fileName, int index) { String rawAndProcDataFileName = String.format("%s/%s_%d_processed.txt", RAW_DATA_DIR, fileName, index); log("write raw data and process data into file: " + rawAndProcDataFileName); BufferedWriter fw = null; try { fw = new BufferedWriter(new FileWriter(new File(rawAndProcDataFileName), false)); // Show the number of jankiness first: fw.write(String.format("Jankiness count: %d\n", getVsyncJankiness())); fw.write(String.format("Max accumulated frames: %d\n", getMaxDeltaVsync())); fw.write(String.format("Frame rate is: %f\n", getFrameRate())); // refresh period fw.write(String.valueOf(mRefreshPeriod)); fw.write("\n"); fw.write("app\tvsync\tset\tdelta(vsync)\tdelta^2(vsync)\t" + "delta^2(vsync)/refreshPeriod\t normalized delta^2(vsync)\n"); for (int i = 0; i < mFrameLatencySampleSize; i++) { // write raw data List rawData = mFrameBufferData.get(i); String line = String.format("%s\t%s\t%s\t%d\t%d\t%f\t%d\n", rawData.get(0), rawData.get(1), rawData.get(2), mDeltaVsync[i], mDelta2Vsync[i], mNormalizedDelta2Vsync[i], mRoundNormalizedDelta2Vsync[i]); fw.write(line); } } catch (IOException e) { log("Open file error: " + e.toString()); } finally { try { if (fw != null) { fw.flush(); fw.close(); } } catch (IOException e) { Log.e(TAG, "close file exception: ", e); } } } private static void log(String msg) { Log.v(TAG, msg); } }