From 64313ae7fc07f75eb4c2d00320704515b4deaba1 Mon Sep 17 00:00:00 2001
From: Yongqin Liu <yongqin.liu@linaro.org>
Date: Thu, 15 Dec 2016 14:18:25 +0800
Subject: android boottime2: collect time from init start to surfaceflinger
 start

CONSOLE_SECONDS is the time from kernel start to init started,
and the TIME_VALUE is reported by surfaceflinger service
which is the time from surfaceflinger started to UI booted up.

There is still the time from point init started to the point
service surfaceflinger started point not collected.

This change is to collect that time, and add it into the total time.

Change-Id: I4dbd8a3ca4d2afb536b65cc9bc245ce30dc06b99
Signed-off-by: Yongqin Liu <yongqin.liu@linaro.org>
---
 android/scripts/boottime2.sh | 26 ++++++++++++++++++++------
 1 file changed, 20 insertions(+), 6 deletions(-)

(limited to 'android')

diff --git a/android/scripts/boottime2.sh b/android/scripts/boottime2.sh
index d9734fb..d08561b 100755
--- a/android/scripts/boottime2.sh
+++ b/android/scripts/boottime2.sh
@@ -30,7 +30,8 @@
 ##    (assuming kernel started at 0 timestamp in this script)
 ##
 ##        TOTAL_TIME:
-##            the sum of KERNEL_BOOT_TIME and ANDROID_BOOT_TIME
+##            the sum of KERNEL_BOOT_TIME, INIT_TO_SURFACEFLINGER_START_TIME,
+##            and ANDROID_BOOT_TIME
 ##
 ##        KERNEL_BOOT_TIME:
 ##            from kernel started to line "Freeing unused kernel memory" printed,
@@ -45,6 +46,10 @@
 ##            it does not include the time from init start to the time
 ##            surfaceflinger service started
 ##
+##        INIT_TO_SURFACEFLINGER_START_TIME:
+##            from the time "Freeing unused kernel memory" printed in dmesg
+##            to the time "init: Starting service 'surfaceflinger'..." is printed
+##
 ##        Also following time values are gotten from dmesg log information,
 ##        they are not accurate as what we expects, but are able to be used for
 ##        reference and used for checking our boot time improvements
@@ -103,7 +108,7 @@ getBootTimeInfoFromDmesg(){
     CONSOLE_SECONDS_START=0
     CONSOLE_SECONDS_END=$(getTime "Freeing unused kernel memory")
     if [ ! -z "${CONSOLE_SECONDS_END}" ] && [ ! -z "${CONSOLE_SECONDS_START}" ]; then
-        CONSOLE_SECONDS=$(echo "$CONSOLE_SECONDS_END $CONSOLE_SECONDS_START - p" | dc)
+        CONSOLE_SECONDS=$(echo "${CONSOLE_SECONDS_END} ${CONSOLE_SECONDS_START} - p" | dc)
         output_test_result "KERNEL_BOOT_TIME" "pass" "${CONSOLE_SECONDS}" "s"
     else
         output_test_result "KERNEL_BOOT_TIME" "fail" "-1" "s"
@@ -136,6 +141,15 @@ getBootTimeInfoFromDmesg(){
         output_test_result "BOOTANIM_TIME" "fail" "-1" "s"
     fi
 
+    POINT_INIT_START=$(getTime "Freeing unused kernel memory")
+    POINT_SERVICE_SURFACEFLINGER_START=$(getTime "init: Starting service 'surfaceflinger'..."|tail -n1)
+    if [ ! -z "${POINT_SERVICE_SURFACEFLINGER_START}" ] && [ ! -z "${POINT_INIT_START}" ]; then
+        INIT_TO_SURFACEFLINGER_START_TIME=$(echo "${POINT_SERVICE_SURFACEFLINGER_START} ${POINT_INIT_START} - p" | dc)
+        output_test_result "INIT_TO_SURFACEFLINGER_START_TIME" "pass" "${INIT_TO_SURFACEFLINGER_START_TIME}" "s"
+    else
+        output_test_result "INIT_TO_SURFACEFLINGER_START_TIME" "fail" "-1" "s"
+    fi
+
     ## When there are 2 lines of "Boot is finished",
     ## it mostly means that the surfaceflinger service restarted by some reason
     ## but here when there are multiple lines of "Boot is finished",
@@ -153,16 +167,16 @@ getBootTimeInfoFromDmesg(){
     fi
 
     SERVICE_START_TIME_INFO=$(grep "healthd:" "${LOG_DMESG}"|head -n 1)
-    SERVICE_START_TIME_END=$(echo "$SERVICE_START_TIME_INFO"|cut -d] -f 1|cut -d[ -f2| tr -d " ")
+    SERVICE_START_TIME_END=$(echo "${SERVICE_START_TIME_INFO}"|cut -d] -f 1|cut -d[ -f2| tr -d " ")
     if [ ! -z "${SERVICE_START_TIME_END}" ] && [ ! -z "${CONSOLE_SECONDS_START}" ]; then
-        SERVICE_START_TIME=$(echo "$SERVICE_START_TIME_END $CONSOLE_SECONDS_START - p" | dc)
+        SERVICE_START_TIME=$(echo "${SERVICE_START_TIME_END} ${CONSOLE_SECONDS_START} - p" | dc)
         output_test_result "ANDROID_SERVICE_START_TIME" "pass" "${SERVICE_START_TIME}" "s"
     else
         output_test_result "ANDROID_SERVICE_START_TIME" "fail" "-1" "s"
     fi
 
-    if [ ! -z "${CONSOLE_SECONDS}" ] && [ ! -z "${TIME_VALUE}" ]; then
-        TOTAL_SECONDS=$(echo "$CONSOLE_SECONDS $TIME_VALUE" | awk '{printf "%.3f",$1 + $2/1000;}')
+    if [ ! -z "${CONSOLE_SECONDS}" ] && [ ! -z "${TIME_VALUE}" ] && [ ! -z "${INIT_TO_SURFACEFLINGER_START_TIME}" ]; then
+        TOTAL_SECONDS=$(echo "${CONSOLE_SECONDS} ${INIT_TO_SURFACEFLINGER_START_TIME} ${TIME_VALUE}" | awk '{printf "%.3f",$1 + $2 + $3/1000;}')
         output_test_result "TOTAL_BOOT_TIME" "pass" "${TOTAL_SECONDS}" "s"
     else
         output_test_result "TOTAL_BOOT_TIME" "fail" "-1" "s"
-- 
cgit v1.2.3