Boot time

BootEvent:

cat /proc/bootprof    /** M: Mtprof tool @{ */

LINUX/android/system/core/rootdir/init.rc
INIT: on init start

LINUX/android/device/mediatek/mt6795/init.mt6795.rc
INIT:Mount_START
INIT:Mount_END

LINUX/android/frameworks/base/core/java/com/android/internal/os/ZygoteInit.java
Zygote:Preload

frameworks/native/services/surfaceflinger/mediatek/SurfaceFlinger.cpp
frameworks/native/services/surfaceflinger/SurfaceFlinger.cpp
BOOT_Animation:START
BOOT_Animation:END

./services/java/com/android/server/SystemServer.java
Android:SysServerInit_START

frameworks/base/services/core/java/com/android/server/pm/PackageManagerService.java
Android:PackageManagerService_Start

frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
AP_Init:[]

Log:

Boot animation time:

frameworks/native/services/surfaceflinger/SurfaceFlinger.cpp
 316 void SurfaceFlinger::bootFinished()
 317 {
 318     const nsecs_t now = systemTime();
 319     const nsecs_t duration = now - mBootTime;
 320     ALOGI("Boot is finished (%ld ms)", long(ns2ms(duration)) );
 321     mBootFinished = true;
 322
 323     // wait patiently for the window manager death
 324     const String16 name("window");
 325     sp<IBinder> window(defaultServiceManager()->getService(name));
 326     if (window != 0) {
 327         window->linkToDeath(static_cast<IBinder::DeathRecipient*>(this));
 328     }
 329
 330     // stop boot animation
 331     // formerly we would just kill the process, but we now ask it to exit so it
 332     // can choose where to stop the animation.
 333     property_set("service.bootanim.exit", "1");
 334
 335 #ifdef MTK_AOSP_ENHANCEMENT
 336     // boot time profiling
 337     ALOG(LOG_INFO,"boot","BOOTPROF:BootAnimation:End:%ld", long(ns2ms(systemTime())));
 338     bootProf(0);
 339     SFWatchDog::getInstance()->setThreshold(500);
 340 #endif
 341 }

Scan package time:

frameworks/base/services/core/java/com/android/server/pm/PackageManagerService.java
            /** M: Add PMS scan package time log @{ */
            startScanTime = SystemClock.uptimeMillis();
            Slog.d(TAG, "scan package: " + file.toString() + " , start at: " + startScanTime + "ms.");
            /** M: Add PMS scan package time log @{ */
            endScanTime = SystemClock.uptimeMillis();
            Slog.d(TAG, "scan package: " + file.toString() + " , end at: " + endScanTime + "ms. elapsed time = " + (endScanTime - startScanTime) + "ms.");

            Slog.i(TAG, "Time to scan packages: "
                    + ((SystemClock.uptimeMillis()-startTime)/1000f)
                    + " seconds");

AP initialization time:

frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
            StringBuilder buf = mStringBuilder;
            buf.setLength(0);
            buf.append("Start proc ");
            buf.append(app.processName);
            if (!isActivityProcess) {
                buf.append(" [");
                buf.append(entryPoint);
                buf.append("]");
            }
            buf.append(" for ");
            buf.append(hostingType);
            if (hostingNameStr != null) {
                buf.append(" ");
                buf.append(hostingNameStr);
            }
            buf.append(": pid=");
            buf.append(startResult.pid);
            buf.append(" uid=");
            buf.append(uid);
            buf.append(" gids={");
            if (gids != null) {
                for (int gi=0; gi<gids.length; gi++) {
                    if (gi != 0) buf.append(", ");
                    buf.append(gids[gi]);
                }
            }
            buf.append("}");
            if (requiredAbi != null) {
                buf.append(" abi=");
                buf.append(requiredAbi);
            }
            Slog.i(TAG, buf.toString());

System server blocked and killed by WatchDag

 如何從各種 log找出造成 System server block的原因

event_log:

07-12 01:42:44.727   956  1520 I [2802]  : Blocked in handler on main thread (main)

main_log:

06-13 15:55:55.725  9028  9028 I AEE/AED : $** *** *** *** *** *** *** *** Fatal *** *** *** *** *** *** *** **$
06-13 15:55:55.725  9028  9028 I AEE/AED : Build Info: 'L0.MP6:ALPS.L0.MP6.TC9SP.V1.38_FIH6795.LWT.S50.L_P43:MT6795:S01,alps/hollyds/hollyds:5.0/2.60.J.1.3_3_04/1434012189:userdebug/test-keys'
06-13 15:55:55.725  9028  9028 I AEE/AED : Flavor Info: 'None'
06-13 15:55:55.725  9028  9028 I AEE/AED : Exception Log Time:[Sat Jun 13 15:55:55 CST 2015] [91427.879630]
06-13 15:55:55.725  9028  9028 I AEE/AED :
06-13 15:55:55.725  9028  9028 V AEE/AED : Write: Req.AE_REQ_CLASS, seq:0
06-13 15:55:55.727  9028  9028 V AEE/AED : Read: Rsp.AE_REQ_CLASS, seq:0, 0, 4
06-13 15:55:55.727  9028  9028 D AEE/AED :   Got data:SWT
06-13 15:55:55.727  9028  9028 I AEE/AED : SWT
06-13 15:55:55.727  9028  9028 V AEE/AED : Write: Req.AE_REQ_TYPE, seq:1
06-13 15:55:55.727  9028  9028 V AEE/AED : Read: Rsp.AE_REQ_TYPE, seq:1, 0, 17
06-13 15:55:55.827  9028  9028 D AEE/AED :   Type:system_server_watchdog
06-13 15:55:55.828  9028  9028 I AEE/AED : system_server_watchdog
06-13 15:55:55.828  9028  9028 V AEE/AED : Write: Req.AE_REQ_PROCESS, seq:2
06-13 15:55:55.828   799  1367 D AEE/LIBAEE: shell: got the request (cmd:Req,AE_REQ_PROCESS)
06-13 15:55:55.829  9028  9028 V AEE/AED : Read: Rsp.AE_REQ_PROCESS, seq:2, 0, e
06-13 15:55:55.829  9028  9028 D AEE/AED :   Process:system_server
06-13 15:55:55.829  9028  9028 I AEE/AED : system_server
06-13 15:55:55.830  9028  9028 V AEE/AED : Write: Req.AE_REQ_MODULE, seq:3
06-13 15:55:55.830  9028  9028 V AEE/AED : Read: Rsp.AE_REQ_MODULE, seq:3, 0, 1
06-13 15:55:55.830  9028  9028 D AEE/AED :   Module:
06-13 15:55:55.830  9028  9028 V AEE/AED : Write: Req.AE_REQ_BACKTRACE, seq:4
06-13 15:55:55.831  9028  9028 V AEE/AED : Read: Rsp.AE_REQ_BACKTRACE, seq:4, 0, bd
06-13 15:55:55.831  9028  9028 D AEE/AED :   Backtrace:Process: system_server
06-13 15:55:55.831  9028  9028 D AEE/AED : Subject: Blocked in handler on main thread (main)
06-13 15:55:55.831  9028  9028 D AEE/AED : Build: alps/hollyds/hollyds:5.0/2.60.J.1.3_3_04/1434012189:userdebug/test-keys
06-13 15:55:55.831  9028  9028 D AEE/AED :
06-13 15:55:55.831  9028  9028 D AEE/AED :
06-13 15:55:55.831  9028  9028 D AEE/AED : Unable to open log device 'crash'
06-13 15:55:55.831  9028  9028 D AEE/AED :
06-13 15:55:55.831  9028  9028 I AEE/AED : Process: system_server
06-13 15:55:55.831  9028  9028 I AEE/AED : Subject: Blocked in handler on main thread (main)
..........
06-13 15:55:42.483   799  1367 I Process : Sending signal. PID: 799 SIG: 3

sys_log:

06-13 15:55:33.637   799  1367 E Watchdog: **SWT happen **Blocked in handler on main thread (main)
.......
06-13 15:56:00.575   799  1367 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in handler on main thread (main)
06-13 15:56:00.576   799  1367 W Watchdog: main thread stack trace:
06-13 15:56:00.593   799  1367 W Watchdog:     at android.media.ToneGenerator.native_setup(Native Method)
06-13 15:56:00.593   799  1367 W Watchdog:     at android.media.ToneGenerator.<init>(ToneGenerator.java:746)
06-13 15:56:00.593   799  1367 W Watchdog:     at com.android.server.notification.NotificationManagerService$2.onReceive(NotificationManagerService.java:775)
06-13 15:56:00.593   799  1367 W Watchdog:     at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:912)
06-13 15:56:00.593   799  1367 W Watchdog:     at android.os.Handler.handleCallback(Handler.java:815)
06-13 15:56:00.593   799  1367 W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:104)
06-13 15:56:00.593   799  1367 W Watchdog:     at android.os.Looper.loop(Looper.java:194)
06-13 15:56:00.593   799  1367 W Watchdog:     at com.android.server.SystemServer.run(SystemServer.java:359)
06-13 15:56:00.593   799  1367 W Watchdog:     at com.android.server.SystemServer.main(SystemServer.java:227)
06-13 15:56:00.593   799  1367 W Watchdog:     at java.lang.reflect.Method.invoke(Native Method)
06-13 15:56:00.593   799  1367 W Watchdog:     at java.lang.reflect.Method.invoke(Method.java:372)
06-13 15:56:00.596   799  1367 W Watchdog:     at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:955)
06-13 15:56:00.597   799  1367 W Watchdog:     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:750)

如何從Backtrace中尋找block的原因：

1. 看 Process是 block在哪一個 thread
2. Trace block tread的 callstack，觀察 class name或 function name，尋找可能造成block的地方
    (不管是在 Java code或 native code)
3. 如果是 block在 main thread，從 call stack中又無法看出可能造成 block的地方，可以嘗試搜  
    尋同一個 process下的其他 tread的 call stack，觀察是否有和 main thread呼叫相同 method的地
    方

Backtrace:

----- pid 956 at 2015-07-12 09:42:08 -----
Cmd line: system_server
............
DALVIK THREADS (111):
"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x747d7fa8 self=0x558db4b0e0
  | sysTid=956 nice=-2 cgrp=apps sched=0/0 handle=0x7f88880150
  | state=S schedstat=( 2873204364724 2124560498532 5319630 ) utm=153154 stm=134166 core=7 HZ=100
  | stack=0x7fcc017000-0x7fcc019000 stackSize=8MB
  | held mutexes=
  kernel: __switch_to+0x70/0x7c
  kernel: binder_thread_read+0x47c/0xec4
  kernel: binder_ioctl+0x3f8/0x828
  kernel: do_vfs_ioctl+0x4c4/0x598
  kernel: SyS_ioctl+0x5c/0x88
  kernel: cpu_switch_to+0x48/0x4c
  native: #00 pc 0005eeb4  /system/lib64/libc.so (__ioctl+4)
  native: #01 pc 0006882c  /system/lib64/libc.so (ioctl+100)
  native: #02 pc 00028544  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+164)
  native: #03 pc 00028fa4  /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+112)
  native: #04 pc 00029218  /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+176)
  native: #05 pc 0001ff18  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+64)
  native: #06 pc 0008aa10  /system/lib64/libmedia.so (???)
  native: #07 pc 00071c38  /system/lib64/libmedia.so (android::AudioSystem::getDevicesForStream(audio_stream_type_t)+40)
  native: #08 pc 000264b8  /system/framework/arm64/boot.oat (Java_android_media_AudioSystem_getDevicesForStream__I+144)
  at android.media.AudioSystem.getDevicesForStream(Native method)
  at android.media.AudioService.getDeviceForStream(AudioService.java:3399)
  at android.media.AudioService.getStreamVolume(AudioService.java:1698)
  at android.media.AudioManager.getStreamVolume(AudioManager.java:961)
  at com.android.server.notification.NotificationManagerService.buzzBeepBlinkLocked(NotificationManagerService.java:1966)
  at com.android.server.notification.NotificationManagerService.access$3600(NotificationManagerService.java:128)
  at com.android.server.notification.NotificationManagerService$7.run(NotificationManagerService.java:1880)
  - locked <0x3d78bf02> (a java.util.ArrayList)
  at android.os.Handler.handleCallback(Handler.java:739)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:135)
  at com.android.server.SystemServer.run(SystemServer.java:295)
  at com.android.server.SystemServer.main(SystemServer.java:183)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1016)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:811)
............

"NetworkPolicy" prio=5 tid=42 Native

  | group="main" sCount=1 dsCount=0 obj=0x139b2860 self=0x557590bc50

  | sysTid=1191 nice=0 cgrp=apps sched=0/0 handle=0x557523dcb0

  | state=S schedstat=( 66132269378 123944333623 433825 ) utm=3755 stm=2858 core=5 HZ=100

  | stack=0x7f6d87d000-0x7f6d87f000 stackSize=1036KB

  | held mutexes=

  kernel: __switch_to+0x70/0x7c

  kernel: binder_thread_read+0x47c/0xec4

  kernel: binder_ioctl+0x3f8/0x828

  kernel: do_vfs_ioctl+0x4c4/0x598

  kernel: SyS_ioctl+0x5c/0x88

  kernel: cpu_switch_to+0x48/0x4c

  native: #00 pc 0005eeb4  /system/lib64/libc.so (__ioctl+4)

  native: #01 pc 0006882c  /system/lib64/libc.so (ioctl+100)

  native: #02 pc 00028544  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+164)

  native: #03 pc 00028fa4  /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+112)

  native: #04 pc 00029218  /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+176)

  native: #05 pc 0001ff18  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+64)

  native: #06 pc 000d99dc  /system/lib64/libandroid_runtime.so (???)

  native: #07 pc 010e0fec  /system/framework/arm64/boot.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+212)

  at android.os.BinderProxy.transactNative(Native method)

  at android.os.BinderProxy.transact(Binder.java:501)

  at com.android.internal.telephony.ISub$Stub$Proxy.getDefaultDataSubId(ISub.java:845)

  at android.telephony.SubscriptionManager.getDefaultDataSubId(SubscriptionManager.java:887)

  at com.android.server.net.NetworkPolicyManagerService.isDdsSimStateReady(NetworkPolicyManagerService.java:2269)

  at com.android.server.net.NetworkPolicyManagerService.setNetworkTemplateEnabled(NetworkPolicyManagerService.java:1019)

  at com.android.server.net.NetworkPolicyManagerService.updateNetworkEnabledLocked(NetworkPolicyManagerService.java:989)

  at com.android.server.net.NetworkPolicyManagerService$7.onReceive(NetworkPolicyManagerService.java:563)

  - locked <0x3532129f> (a java.lang.Object)

  at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:869)

  at android.os.Handler.handleCallback(Handler.java:739)

  at android.os.Handler.dispatchMessage(Handler.java:95)

  at android.os.Looper.loop(Looper.java:135)

  at android.os.HandlerThread.run(HandlerThread.java:61)

Keycode value

http://blog.csdn.net/xl_tang/article/details/8720953

frameworks/base/core/java/android/view/KeyEvent.java

log example:
05-06 08:07:01.682 25467 25467 I View    : Key down dispatch to com.facebook.feed.ui.NewsFeedListView{1f1bf432 VFED.VC. .F.....D 0,-144-1080,1413 #102000a android:id/list}, event = KeyEvent { action=ACTION_DOWN, keyCode=KEYCODE_BACK, scanCode=0, metaState=0, flags=0x48, repeatCount=0, eventTime=51223965, downTime=51223965, deviceId=-1, source=0x101 }


06-20 23:14:30.377   814  1124 D WindowManager: interceptKeyTq keycode=26 interactive=true keyguardActive=true policyFlags=22000000 down =true canceled = false isWakeKey=false mVolumeDownKeyTriggered =false mVolumeUpKeyTriggered =false result = 1 useHapticFeedback = false isInjected = false
06-20 23:14:30.411   814  1124 D WindowManager: interceptKeyTq keycode=26 interactive=true keyguardActive=true policyFlags=22000000 down =false canceled = false isWakeKey=false mVolumeDownKeyTriggered =false mVolumeUpKeyTriggered =false result = 1 useHapticFeedback = false isInjected = false

Screen pinning

Reference:

https://developer.android.com/about/versions/android-5.0.html#ScreenPinning
http://blog.csdn.net/aaa111/article/details/43866981

Abrtraction:

打開Screen pinning後，通知欄和狀態欄會隱藏起來，Home key和Recent app key會失效，而且不允許啟動其它activity

How to open/close screen pinning:

手動：
從Settings -> Security -> Screen Pinning來釘選指定的app
同時長按 Back key和 Recent app key來關閉screen pinning

程式：
從app中呼叫startLockTask() 來釘選app。
若app不具有系統權限，則會跳出提示視窗，詢問使用者是否要執行Screen pinning
若app具有系統權限，可以直接呼叫setLockTaskPackages (ComponentName admin, String[] packages) ，省略詢問使用者的步驟
從app中呼叫stopLockTask()來關閉screen pinning

Source code:

Settings
.packages/app/Settings/src/com/android/settings/ScreenPinningSettings.java
    private void setLockToAppEnabled(boolean isEnabled) {
        Settings.System.putInt(getContentResolver(), Settings.System.LOCK_TO_APP_ENABLED,
                isEnabled ? 1 : 0);
    }

framework/base
.frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
void startLockTaskMode(TaskRecord task) {

.frameworks/base/services/core/java/com/android/server/am/ActivityStackSupervisor.java
void setLockTaskModeLocked(TaskRecord task, boolean isLocked)

public void handleMessage(Message msg) {
                ......
                case LOCK_TASK_START_MSG: {
                    // When lock task starts, we disable the status bars.
                    try {
                        if (mLockTaskNotify == null) {
                            mLockTaskNotify = new LockTaskNotify(mService.mContext);
                        }
                        mLockTaskNotify.show(true);                  // Show toast message
                        mLockTaskIsLocked = msg.arg2 == 0;
                        if (getStatusBarService() != null) {
                            int flags =
                                    StatusBarManager.DISABLE_MASK ^ StatusBarManager.DISABLE_BACK;
                            if (!mLockTaskIsLocked) {
                                flags ^= StatusBarManager.DISABLE_HOME
                                        | StatusBarManager.DISABLE_RECENT;
                            }
                            getStatusBarService().disable(flags, mToken,
                                    mService.mContext.getPackageName());
                        }
                        mWindowManager.disableKeyguard(mToken, LOCK_TASK_TAG);
                        if (getDevicePolicyManager() != null) {
                            getDevicePolicyManager().notifyLockTaskModeChanged(true,
                                    (String)msg.obj, msg.arg1);
                        }
                    } catch (RemoteException ex) {
                        throw new RuntimeException(ex);
                    }
                } break;

                case LOCK_TASK_END_MSG: {
                    // When lock task ends, we enable the status bars.
                    try {
                        if (getStatusBarService() != null) {
                            getStatusBarService().disable(StatusBarManager.DISABLE_NONE, mToken,
                                    mService.mContext.getPackageName());
                        }
                        mWindowManager.reenableKeyguard(mToken);
                        if (getDevicePolicyManager() != null) {
                            getDevicePolicyManager().notifyLockTaskModeChanged(false, null,
                                    msg.arg1);
                        }
                        if (mLockTaskNotify == null) {
                            mLockTaskNotify = new LockTaskNotify(mService.mContext);
                        }
                        mLockTaskNotify.show(false);
                        try {
                            boolean shouldLockKeyguard = Settings.System.getInt(
                                    mService.mContext.getContentResolver(),
                                    Settings.System.LOCK_TO_APP_EXIT_LOCKED) != 0;
                            if (!mLockTaskIsLocked && shouldLockKeyguard) {
                                mWindowManager.lockNow(null);
                                mWindowManager.dismissKeyguard();
                                new LockPatternUtils(mService.mContext)
                                        .requireCredentialEntry(UserHandle.USER_ALL);
                            }
                        } catch (SettingNotFoundException e) {
                            // No setting, don't lock.
                        }
                    } catch (RemoteException ex) {
                        throw new RuntimeException(ex);
                    }
                } break;

.frameworks/base/services/core/java/com/android/server/am/LockTaskNotify.java
    public void show(boolean starting) {
        int showString = R.string.lock_to_app_exit;
        if (starting) {
            showString = R.string.lock_to_app_start;
        }
        Toast.makeText(mContext, mContext.getString(showString), Toast.LENGTH_LONG).show();
    }

Related issue:

1. Toast messages are not displayed in screen pinning scenarios when accessed through other Users/Guest mode
[Solution1]
.frameworks/base/core/java/android/widget/Toast.java
             params.flags = WindowManager.LayoutParams.FLAG_KEEP_SCREEN_ON
                     | WindowManager.LayoutParams.FLAG_NOT_FOCUSABLE
                     | WindowManager.LayoutParams.FLAG_NOT_TOUCHABLE;
+            // Support multi-user
+            params.privateFlags =
                               WindowManager.LayoutParams.PRIVATE_FLAG_SHOW_FOR_ALL_USERS;         }
 
[Solution2]
https://android.googlesource.com/platform/frameworks/base/+/a585268aff94b620b2c22e9ba3ae1163bb5dc8a8%5E%21/#F1
.frameworks/base/core/java/android/widget/Toast.java
     public int getYOffset() {
         return mTN.mY;
     }
+
+   /**
+   * Gets the LayoutParams for the Toast window.
+   * @hide
+   */
+   public WindowManager.LayoutParams getWindowParams() {
+       return mTN.mParams;
+ }

.frameworks/base/services/core/java/com/android/server/am/LockTaskNotify.java
 import android.content.Context;
import android.os.Handler;
import android.os.Message;
+import android.view.WindowManager; import android.view.accessibility.AccessibilityManager;
import android.widget.Toast;

@@ -56,8 +57,7 @@
     if (mLastToast != null) {
         mLastToast.cancel();
     }
-   mLastToast = Toast.makeText(mContext, text, Toast.LENGTH_LONG);
-   mLastToast.show();
+   mLastToast = makeAllUserToastAndShow(text); }

public void show(boolean starting) {
@@ -65,7 +65,15 @@
     if (starting) {
         showString = R.string.lock_to_app_start;
     }
-    Toast.makeText(mContext, mContext.getString(showString), Toast.LENGTH_LONG).show();+   makeAllUserToastAndShow(mContext.getString(showString));
+   }
+
+   private Toast makeAllUserToastAndShow(String text) {
+   Toast toast = Toast.makeText(mContext, text, Toast.LENGTH_LONG);
+   toast.getWindowParams().privateFlags |=
+   WindowManager.LayoutParams.PRIVATE_FLAG_SHOW_FOR_ALL_USERS;
+   toast.show();
+   return toast; }