本文出自:【張旭童的簡書】 (http://www.itdecent.cn/users/8e91ff99b072/latest_articles)
想來gayhub和我gaygayup:【mcxtzhang的Github主頁】https://github.com/mcxtzhang
背景
最近在做一些性能監(jiān)控的工作,其中線下監(jiān)控fps這一項,經(jīng)過調(diào)研,最終采用dumpsys gfxinfo的方式。
在6.0+的手機中執(zhí)行如下命令,
adb shell dumpsys gfxinfo 包名
可以得到一些log:
Applications Graphics Acceleration Info:
Uptime: 3820706382 Realtime: 3903615964
** Graphics info for pid 427 [包名] **
Stats since: 3820661771494092ns
Total frames rendered: 201
//重點關(guān)注對象
Janky frames: 76 (37.81%)
50th percentile: 6ms
90th percentile: 19ms
95th percentile: 61ms
99th percentile: 300ms
Number Missed Vsync: 14
Number High input latency: 0
Number Slow UI thread: 17
Number Slow bitmap uploads: 5
Number Slow issue draw commands: 60
........
//重點關(guān)注對象
ActivityName/android.view.ViewRootImpl@d4c0f16 (visibility=0)
//每個Activity的每一幀的原始數(shù)據(jù),包含每個階段的時間戳
---PROFILEDATA---
Flags,IntendedVsync,Vsync,OldestInputEvent,NewestInputEvent,HandleInputStart,AnimationStart,PerformTraversalsStart,DrawStart,SyncQueued,SyncStart,IssueDrawCommandsStart,SwapBuffers,FrameCompleted,
0,3820697872348436,3820697872348436,9223372036854775807,0,3820697872662836,3820697872693045,3820697872814399,3820697872932628,3820697873194607,3820697873228461,3820697873328982,3820697873869086,3820697876514920,
0,3820697889204506,3820697889204506,9223372036854775807,0,3820697889517524,3820697889547211,3820697889672211,3820697889801899,3820697890120649,3820697890156586,3820697890267524,3820697890787836,3820697892957628,
0,3820697906060465,3820697906060465,9223372036854775807,0,3820697906622211,3820697906650857,3820697906761795,3820697906888357,3820697907180024,3820697907215961,3820697907325857,3820697907809190,3820697909209190,
0,3820697922916378,3820697922916378,9223372036854775807,0,3820697923237315,3820697923265440,3820697923397732,3820697923533149,3820697923806586,3820697923837315,3820697923936795,3820697924388878,3820697927055024,
0,3820697939772285,3820697939772285,9223372036854775807,0,3820697940389920,3820697940418565,3820697940532628,3820697940652420,3820697940915961,3820697940948774,3820697941046690,3820697941496170,3820697943844086,
0,3820697956628358,3820697956628358,9223372036854775807,0,3820697956922732,3820697956952940,3820697957073774,3820697957197732,3820697957457107,3820697957490961,3820697957583149,3820697958036795,3820697959429503,
............
其中有一項名為:Janky frames的數(shù)據(jù)引起了我們的興趣。
Janky frames該如何理解呢?參考官方文檔1 的說明,似乎就是掉幀的數(shù)量。
可如果按照掉幀的數(shù)量來理解,這份log顯示的掉幀率高達37.81%,一個app如果近40%的幀都被skip,用戶不可能毫無感知。
但在我們測試時,沒有感覺到明顯的卡頓。(且根據(jù)原始數(shù)據(jù),用另外一套計算方式,算出的幀率fps值也與掉幀率的百分比矛盾)
但這Janky frames畢竟是官方adb命令給出的值,具有一定的權(quán)威性,于是我們開始自我懷疑,
- 是我們的眼睛沒有看出卡頓?
- 是我們計算幀率fps的方式出現(xiàn)了問題?
- ...
由于官方在log中并未給出實際fps的值,于是為了探究問題出在哪里,也為了參考官方的計算標準,即如何判定一幀出現(xiàn)了janky,我便把黑手伸向了無辜的源碼,畢竟源碼之下,了無秘密。
遂,現(xiàn)在的目標是:
- 找到adb shell dumpsys gfxinfo的源碼
- 找到源碼里關(guān)于
Janky frame的計算方法
找到gfxinfo源碼
經(jīng)過搜索,在Android dumpsys工具分析文中中得知,當我們執(zhí)行adb shell dumpsys后,根據(jù)后面不同的參數(shù),例如meminfo 、gfxinfo,實際上是通過ServiceManager->checkService(services[i])方法,從ServiceManager中取出對應(yīng)服務(wù)的Binder對象,并最終通過service->dump(STDOUT_FILENO, args)調(diào)用對應(yīng)服務(wù)Binder對象的dump()方法執(zhí)行具體命令。
這些系統(tǒng)服務(wù)的注冊,是在AMS(ActivityManagerService.java)里的setSystemProcess()里完成的,
public void setSystemProcess() {
try {
//在ServiceManager中注冊服務(wù)
//"activity";
ServiceManager.addService(Context.ACTIVITY_SERVICE, this, true);
ServiceManager.addService(ProcessStats.SERVICE_NAME, mProcessStats);
ServiceManager.addService("meminfo", new MemBinder(this));
ServiceManager.addService("gfxinfo", new GraphicsBinder(this));
ServiceManager.addService("dbinfo", new DbBinder(this));
...
} catch (PackageManager.NameNotFoundException e) {
throw new RuntimeException(
"Unable to find android system package", e);
}
}
可以看到,我們熟悉的 "activity"、"meminfo"以及本文的主角"gfxinfo"都在其中注冊。
java層源碼
順藤摸瓜,我們看看GraphicsBinder這個類以及它的dump()方法:
static class GraphicsBinder extends Binder {
ActivityManagerService mActivityManagerService;
GraphicsBinder(ActivityManagerService activityManagerService) {
mActivityManagerService = activityManagerService;
}
@Override
protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) {
if (!DumpUtils.checkDumpAndUsageStatsPermission(mActivityManagerService.mContext,
"gfxinfo", pw)) return;
//調(diào)用ams的dumpGraphicsHardwareUsage()方法
mActivityManagerService.dumpGraphicsHardwareUsage(fd, pw, args);
}
}
dump()方法很簡單,僅僅驗證權(quán)限后調(diào)用ams的dumpGraphicsHardwareUsage()方法,繼續(xù)跟進:
final void dumpGraphicsHardwareUsage(FileDescriptor fd,
PrintWriter pw, String[] args) {
//根據(jù)args參數(shù),參數(shù)里包含進程名 或者進程id,得到指定進程。 如果args參數(shù)里不包含進程名,則得到所有進程
ArrayList<ProcessRecord> procs = collectProcesses(pw, 0, false, args);
//沒有符合條件的進程時的輸出
if (procs == null) {
pw.println("No process found for: " + args[0]);
return;
}
//執(zhí)行命令時的時間
long uptime = SystemClock.uptimeMillis();
long realtime = SystemClock.elapsedRealtime();
pw.println("Applications Graphics Acceleration Info:");
pw.println("Uptime: " + uptime + " Realtime: " + realtime);
//循環(huán)進程列表
for (int i = procs.size() - 1 ; i >= 0 ; i--) {
ProcessRecord r = procs.get(i);
if (r.thread != null) {
pw.println("\n** Graphics info for pid " + r.pid + " [" + r.processName + "] **");
pw.flush();
try {
TransferPipe tp = new TransferPipe();
try {
//重點,執(zhí)行每個進程的ApplicationThread的dumpGfxInfo()方法
r.thread.dumpGfxInfo(tp.getWriteFd(), args);
tp.go(fd);
} finally {
tp.kill();
}
} catch (IOException e) {
pw.println("Failure while dumping the app: " + r);
pw.flush();
} catch (RemoteException e) {
pw.println("Got a RemoteException while dumping the app " + r);
pw.flush();
}
}
}
}
可以看到,我們關(guān)心的核心輸出(Janky frames部分)以進程區(qū)分,并在ApplicationThread.dumpGfxInfo()方法中輸出。
ApplicationThread在ActivityThread.java中,繼續(xù)跟進:
@Override
public void dumpGfxInfo(ParcelFileDescriptor pfd, String[] args) {
//jni ,janky frames輸出就在其中
dumpGraphicsInfo(pfd.getFileDescriptor());
// java方法,輸出 Profile data in ms: 后面的部分
WindowManagerGlobal.getInstance().dumpGfxInfo(pfd.getFileDescriptor(), args);
IoUtils.closeQuietly(pfd);
}
// ------------------ Regular JNI ------------------------
private native void dumpGraphicsInfo(FileDescriptor fd);
查看WindowManagerGlobal.dumpGfxInfo()方法:
public void dumpGfxInfo(FileDescriptor fd, String[] args) {
FileOutputStream fout = new FileOutputStream(fd);
PrintWriter pw = new FastPrintWriter(fout);
try {
synchronized (mLock) {
final int count = mViews.size();
pw.println("Profile data in ms:");
for (int i = 0; i < count; i++) {
ViewRootImpl root = mRoots.get(i);
String name = getWindowName(root);
pw.printf("\n\t%s (visibility=%d)", name, root.getHostVisibility());
ThreadedRenderer renderer =
root.getView().mAttachInfo.mThreadedRenderer;
if (renderer != null) {
renderer.dumpGfxInfo(pw, fd, args);
}
}
pw.println("\nView hierarchy:\n");
int viewsCount = 0;
int displayListsSize = 0;
int[] info = new int[2];
for (int i = 0; i < count; i++) {
ViewRootImpl root = mRoots.get(i);
root.dumpGfxInfo(info);
String name = getWindowName(root);
pw.printf(" %s\n %d views, %.2f kB of display lists",
name, info[0], info[1] / 1024.0f);
pw.printf("\n\n");
viewsCount += info[0];
displayListsSize += info[1];
}
pw.printf("\nTotal ViewRootImpl: %d\n", count);
pw.printf("Total Views: %d\n", viewsCount);
pw.printf("Total DisplayList: %.2f kB\n\n", displayListsSize / 1024.0f);
}
} finally {
pw.flush();
}
}
可知,其中輸出的是"Profile data in ms:"后面部分的log,所以,我們關(guān)心的部分就在JNI里了。
C層源碼
看到JNI我是抗拒的,本科時學的那些C、C++早已記不太清,一想到要看C層的源碼,就覺得頭大。原本想溜,但是轉(zhuǎn)念一想,我只需要關(guān)注它對于"Janky frame"的計算方式,無外乎那些數(shù)學運算。只要重點關(guān)注函數(shù)調(diào)用處,搜索關(guān)鍵字,說不定可以找到答案。于是,繼續(xù)跟進。
由于涉及C層的源碼在AndroidStudio中查看不了,下面的分析使用查看framework源碼網(wǎng)站進行。我全局搜索了關(guān)鍵字dumpGraphicsInfo,找到函數(shù)定義處:
[圖片上傳失敗...(image-c02780-1517466253400)]
進入android_view_DisplayListCanvas.cpp查看():
[圖片上傳失敗...(image-1ac76-1517466253400)]
搜索dumpGraphicsMemory:
[圖片上傳失敗...(image-3561dc-1517466253400)]
進入RenderProxy.cpp后,
[圖片上傳失敗...(image-9d5c50-1517466253400)]
由于對c++不是很懂,這一塊的代碼不是很懂,但是從全局搜索只有三處調(diào)用,而且從jankTracker的字樣上可以看出(這一步有一些連蒙帶猜),這里應(yīng)該是正確的方向,繼續(xù)跟進:
在JankTracker.h文件中:
[圖片上傳失敗...(image-5f14bc-1517466253400)]
于是我們進入JankTracker.cpp中查看dumpData()方法的具體實現(xiàn):
[圖片上傳失敗...(image-93dee3-1517466253400)]
看到這里我是既興奮又痛苦。興奮的是我找到了最終log對應(yīng)的輸出之處,痛苦的是,這里僅僅是將ProfileData->jankFrameCount字段輸出,看來革命之路還長,還要找到賦值的地方。
jankFrameCount 賦值之處
全局搜索->jankFrameCount調(diào)用之處,:
[圖片上傳失敗...(image-d7ee56-1517466253400)]
發(fā)現(xiàn)僅在JankTracker.cpp中使用到,在addFrame()函數(shù)中會遞增:
[圖片上傳失敗...(image-1577db-1517466253400)]
可以看出,如果一幀的時間如果小于mFrameInterval,則return,那么jankFrameCount不會遞增,即 每一幀的時間大于等于mFrameInterval,就是Janky frame
看來我們離答案已經(jīng)很接近了,那么mFrameInterval是多少呢?
搜索mFrameInterval是在setFrameInterval()中賦值的:
[圖片上傳失敗...(image-fc007e-1517466253401)]
setFrameInterval()在JankTracker初始化時調(diào)用:
[圖片上傳失敗...(image-ab8fb4-1517466253401)]
根據(jù)官方文檔1以及官方視頻why60fps,刷新頻率fps是60。所以可得frameIntervalNanos約等于16.67ms.
結(jié)論
至此我們可以得出結(jié)論,官方衡量Janky frames的標準:一幀的時間超過16.67ms。
想法
注:以下想法目前還沒有源碼撐腰,并不一定正確,如有錯誤以及知情大佬,煩請指正,謝謝
有上述結(jié)論可以看出 Janky frames確實代表了這一幀的完整繪制時間太久,出現(xiàn)了問題,
那么回到我們文首的問題,某些頁面的Janky frames高達近37.81%,為何我們沒有感到卡頓?以及為何算出來的fps并沒有低于37.2= 60*(1-0.38)?
關(guān)于這個問題,經(jīng)過討論,有以下暫時的想法:
- Android 5.0以后,加入了RenderThread,用于分擔UI Thread的部分繪制工作。即一幀的完整繪制時間 是由UIThread和RenderThread上的耗時相加得到的。
- UI Thread在處理完input animation以及部分draw的工作后,將剩余繪制工作交于RenderThread,UI Thread此時可以繼續(xù)處理下一個VSYNC到來時的工作。
- RenderThread 以及三緩沖機制
[圖片上傳失敗...(image-2f72c8-1517466253401)]
可以看出B先導致了一次視覺上的jank,C理論上也是jank的(相加時間超過了16.67ms),但是由于此時屏幕上顯示的是B,C雖然delay了一幀,但是由于C之前的B已經(jīng)delay了一幀,所以C看起來仍然是緊跟著B顯示在屏幕上,而且A順利的在16.67ms完成了任務(wù),緊跟著C繼續(xù)繪制了,則用戶在視覺上只少看到了一幀。
所以我們的想法是:
在Android5.0+,Janky frames 并不代表用戶視覺上的,顯示在屏幕上的丟幀率,但是它可以代表有問題的幀率,
即這些幀有問題,但最終由于三緩沖機制的背鍋,部分幀沒有最終影響到用戶,
所以實際上的fps值會高于 60(1-掉幀率).*
這個問題后面也會繼續(xù)跟進,做到理據(jù)服。