android boottime2: suppport to collect data from multiple boot

since the the boottime optimization work is very hard,
and boottime reduced will not be obvious compare to
the 20s around value, so use average from multiple time
is important for the boottime optimization check

Change-Id: I9786dbdf5be3109eedf57a0ce0731184f5ab7826
Signed-off-by: Yongqin Liu <yongqin.liu@linaro.org>

3 files changed, 233 insertions, 42 deletions

diff --git a/android/boottime2.yaml b/android/boottime2.yaml
new file mode 100644
index 0000000..b4044bd
--- /dev/null
+++ b/android/boottime2.yaml
@@ -0,0 +1,24 @@
+metadata:
+    name: boottime2
+    format: "Lava-Test-Shell Test Definition 1.0"
+    description: "collect the boottime data many times and try to analyse,
+                  when run more than 4 times(including), the average will be
+                  calculated without the maximum and the minmun, if run less
+                  than or equal to 3 time, the average will be calculated with
+                  all data"
+    maintainer:
+        - yongqin.liu@linaro.org
+    os:
+        - android
+    scope:
+        - performance
+    devices:
+        - juno
+
+params:
+    OPERATION: "COLLECT"
+    COLLECT_NO: "1"
+
+run:
+    steps:
+        - ./android/scripts/boottime2.sh ${OPERATION} ${COLLECT_NO}
diff --git a/android/scripts/boottime2.sh b/android/scripts/boottime2.sh
new file mode 100755
index 0000000..d867b0d
--- /dev/null
+++ b/android/scripts/boottime2.sh
@@ -0,0 +1,162 @@
+#!/system/bin/sh
+
+local_file_path="$0"
+local_file_parent=$(dirname "${local_file_path}")
+local_file_parent=$(cd "${local_file_parent}"||exit; pwd)
+# shellcheck source=android/scripts/common.sh
+. "${local_file_parent}/common.sh"
+
+local_tmp="/data/local/tmp/"
+dir_boottime_data="${local_tmp}/boottime"
+F_RAW_DATA_CSV="${dir_boottime_data}/boot_time_raw_data.csv"
+F_STATISTIC_DATA_CSV="${dir_boottime_data}/boot_time_statistic_data.csv"
+
+
+# dmeg line example
+# [    7.410422] init: Starting service 'logd'...
+getTime(){
+    key=$1
+    if [ -z "${key}" ]; then
+        return
+    fi
+
+    key_line=$(grep "${key}" "${LOG_DMESG}")
+    if [ -n "${key_line}" ]; then
+        timestamp=$(echo "${key_line}"|awk '{print $2}' | awk -F "]" '{print $1}')
+        echo "${timestamp}"
+    fi
+}
+
+getBootTimeInfoFromDmesg(){
+    COLLECT_NO=$1
+
+    LOG_LOGCAT_ALL="${dir_boottime_data}/logcat_all_${COLLECT_NO}.log"
+    LOG_DMESG="${dir_boottime_data}/dmesg_${COLLECT_NO}.log"
+
+    # dmesg starts before all timers are initialized, so kernel reports time as 0.0.
+    # we can't work around this without external time metering.
+    # here we presume kernel message starts from 0
+    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)
+        output_test_result "KERNEL_BOOT_TIME" "pass" "${CONSOLE_SECONDS}" "s"
+    else
+        output_test_result "KERNEL_BOOT_TIME" "fail" "-1" "s"
+    fi
+
+    POINT_FS_MOUNT_START=$(getTime "Freeing unused kernel memory:"|tail -n1)
+    POINT_FS_MOUNT_END=$(getTime "init: Starting service 'logd'...")
+    if [ ! -z "${POINT_FS_MOUNT_END}" ] && [ ! -z "${POINT_FS_MOUNT_START}" ]; then
+        FS_MOUNT_TIME=$(echo "${POINT_FS_MOUNT_END} ${POINT_FS_MOUNT_START} - p" | dc)
+        output_test_result "FS_MOUNT_TIME" "pass" "${FS_MOUNT_TIME}" "s"
+    else
+        output_test_result "FS_MOUNT_TIME" "fail" "-1" "s"
+    fi
+
+    POINT_FS_DURATION_START=$(getTime "init: /dev/hw_random not found"|tail -n1)
+    POINT_FS_DURATION_END=$(getTime "init: Starting service 'logd'...")
+    if [ ! -z "${POINT_FS_DURATION_END}" ] && [ ! -z "${POINT_FS_DURATION_START}" ]; then
+        FS_MOUNT_DURATION=$(echo "${POINT_FS_DURATION_END} ${POINT_FS_DURATION_START} - p" | dc)
+        output_test_result "FS_MOUNT_DURATION" "pass" "${FS_MOUNT_DURATION}" "s"
+    else
+        output_test_result "FS_MOUNT_DURATION" "fail" "-1" "s"
+    fi
+
+    POINT_SERVICE_BOOTANIM_START=$(getTime "init: Starting service \'bootanim\'...")
+    POINT_SERVICE_BOOTANIM_END=$(getTime "init: Service 'bootanim'.* exited with status")
+    if [ ! -z "${POINT_SERVICE_BOOTANIM_END}" ] && [ ! -z "${POINT_SERVICE_BOOTANIM_START}" ]; then
+        BOOTANIM_TIME=$(echo "${POINT_SERVICE_BOOTANIM_END} ${POINT_SERVICE_BOOTANIM_START} - p" | dc)
+        output_test_result "BOOTANIM_TIME" "pass" "${BOOTANIM_TIME}" "s"
+    else
+        output_test_result "BOOTANIM_TIME" "fail" "-1" "s"
+    fi
+
+    TIME_INFO=$(grep "Boot is finished" "${LOG_LOGCAT_ALL}")
+    if [ -z "${TIME_INFO}" ]; then
+        output_test_result "ANDROID_BOOT_TIME" "fail" "-1" "s"
+    else
+        while echo "${TIME_INFO}"|grep -q "("; do
+            TIME_INFO=$(echo "${TIME_INFO}"|cut -d\( -f2-)
+        done
+        TIME_VALUE=$(echo "${TIME_INFO}"|cut -d\  -f1)
+        ANDROID_BOOT_TIME=$(echo "${TIME_VALUE} 1000 / p" | dc)
+        output_test_result "ANDROID_BOOT_TIME" "pass" "${ANDROID_BOOT_TIME}" "s"
+    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 " ")
+    if [ ! -z "${SERVICE_START_TIME_END}" ] && [ ! -z "${CONSOLE_SECONDS_START}" ]; then
+        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
+
+    echo "$CONSOLE_SECONDS $TIME_VALUE 1000 / + p"
+    if [ ! -z "${CONSOLE_SECONDS}" ] && [ ! -z "${TIME_VALUE}" ]; then
+        TOTAL_SECONDS=$(echo "$CONSOLE_SECONDS $TIME_VALUE 1000 / + p" | dc)
+        output_test_result "TOTAL_BOOT_TIME" "pass" "${TOTAL_SECONDS}" "s"
+    else
+        output_test_result "TOTAL_BOOT_TIME" "fail" "-1" "s"
+    fi
+}
+
+OPERATION=$1
+if [ "X${OPERATION}" = "XCOLLECT" ]; then
+    G_VERBOSE_OUTPUT=FALSE
+    G_RECORD_LOCAL_CSV=FALSE
+    COLLECT_NO=$2
+    mkdir -p ${dir_boottime_data}
+
+    # shellcheck disable=SC2035
+    logcat -d -v time *:V > "${dir_boottime_data}/logcat_all_${COLLECT_NO}.log"
+    output_test_result "BOOTTIME_LOGCAT_ALL_COLLECT" "pass"
+    logcat -d -b events -v time > "${dir_boottime_data}/logcat_events_${COLLECT_NO}.log"
+    output_test_result "BOOTTIME_LOGCAT_EVENTS_COLLECT" "pass"
+    dmesg > "${dir_boottime_data}/dmesg_${COLLECT_NO}.log"
+    output_test_result "BOOTTIME_DMESG_COLLECT" "pass"
+elif [ "X${OPERATION}" = "XANALYZE" ]; then
+    count=$2
+    i=1
+    G_RESULT_NOT_RECORD=TRUE
+    G_RECORD_LOCAL_CSV=TRUE
+    export G_RECORD_LOCAL_CSV G_RESULT_NOT_RECORD
+    while true; do
+        if [ $i -gt "$count" ]; then
+            break
+        fi
+        getBootTimeInfoFromDmesg ${i}
+        i=$((i+1))
+    done
+    G_RESULT_NOT_RECORD=FALSE
+    export G_RESULT_NOT_RECORD
+    if [ "X${G_RECORD_LOCAL_CSV}" = "XTRUE" ]; then
+        statistic ${F_RAW_DATA_CSV} 2 |tee ${F_STATISTIC_DATA_CSV}
+        sed -i 's/=/,/' "${F_STATISTIC_DATA_CSV}"
+
+        G_RECORD_LOCAL_CSV=FALSE
+        export G_RECORD_LOCAL_CSV
+        while read -r line; do
+            if ! echo "$line"|grep -q ,; then
+                continue
+            fi
+            key=$(echo "$line"|cut -d, -f1)
+            measurement=$(echo "$line"|cut -d, -f2)
+            units=$(echo "$line"|cut -d, -f3)
+            output_test_result "${key}" "pass" "${measurement}" "${units}"
+        done < "${F_STATISTIC_DATA_CSV}"
+    fi
+    # set again for following output_test_result
+    G_RECORD_LOCAL_CSV=FALSE
+    cd ${local_tmp}|| exit 1
+    tar -czvf boottime.tgz boottime
+    lava-test-run-attach boottime.tgz application/x-gzip
+    output_test_result "BOOTTIME_ANALYZE" "pass"
+else
+    G_VERBOSE_OUTPUT=FALSE
+    G_RECORD_LOCAL_CSV=FALSE
+    export G_VERBOSE_OUTPUT G_RECORD_LOCAL_CSV
+    echo "Not recognised operation"
+    output_test_result "BOOTTIME" "fail"
+fi
diff --git a/android/scripts/common.sh b/android/scripts/common.sh
index bc4a526..b2f9091 100644
--- a/android/scripts/common.sh
+++ b/android/scripts/common.sh
@@ -3,8 +3,10 @@
 G_LOOP_COUNT=12
 G_RECORD_LOCAL_CSV=TRUE
 G_VERBOSE_OUTPUT=FALSE
+G_RESULT_NOT_RECORD=FALSE
 F_RAW_DATA_CSV="/data/local/tmp/lava_test_shell_raw_data.csv"
 F_STATISTIC_DATA_CSV="/data/local/tmp/lava_test_shell_statistic_data.csv"
+var_test_func=""
 
 ## Description:
 ##    output the max value of the passed 2 parameters
@@ -13,10 +15,10 @@ F_STATISTIC_DATA_CSV="/data/local/tmp/lava_test_shell_statistic_data.csv"
 ## Example:
 ##    max=$(f_max "1.5" "2.0")
 f_max(){
-    local val1=$1
-    local val2=$2
-    [ -z "$val1" ] && echo $val2
-    [ -z "$val2" ] && echo $val1
+    val1=$1
+    val2=$2
+    [ -z "$val1" ] && echo "$val2"
+    [ -z "$val2" ] && echo "$val1"
 
     echo "$val1,$val2"|awk -F, '{if($1<$2) print $2; else print $1}'
 }
@@ -28,10 +30,10 @@ f_max(){
 ## Example:
 ##    min=$(f_min "1.5" "2.0")
 f_min(){
-    local val1=$1
-    local val2=$2
-    [ -z "$val1" ] && echo $val1
-    [ -z "$val2" ] && echo $val2
+    val1=$1
+    val2=$2
+    [ -z "$val1" ] && echo "$val1"
+    [ -z "$val2" ] && echo "$val2"
 
     echo "$val1,$val2"|awk -F, '{if($1>$2) print $2; else print $1}'
 }
@@ -48,30 +50,31 @@ f_min(){
 ##    if less than 4 samples for that key/item there, average will be calculated as total/count
 ##    if 4 or more samples for that key/item there, average will be calculated with max and min excluded
 statistic(){
-    local f_data=$1
+    f_data=$1
     if ! [ -f "$f_data" ]; then
         return
     fi
-    local field_no=$2
+    field_no=$2
     if [ -z "$field_no" ]; then
         field_no=2
     fi
-    local total=0
-    local max=0
-    local min=0
-    local old_key=""
-    local new_key=""
-    local count=0
-    local units=""
-    sort ${f_data} >${f_data}.sort
-    for line in $(cat "${f_data}.sort" |tr ' ' '~'); do
+    total=0
+    max=0
+    min=0
+    old_key=""
+    new_key=""
+    count=0
+    units=""
+    sort "${f_data}" >"${f_data}.sort"
+    while read -r line; do
+        line=$(echo "$line"|tr ' ' '~')
         if ! echo "$line"|grep -q ,; then
             continue
         fi
-        new_key=$(echo $line|cut -d, -f1)
-        local measurement_units=$(echo $line|cut -d, -f${field_no})
-        if echo ${measurement_units}|grep -q '~'; then
-            value=$(echo ${measurement_units}|cut -d~ -f1)
+        new_key=$(echo "$line"|cut -d, -f1)
+        measurement_units=$(echo "$line"|cut -d, -f${field_no})
+        if echo "${measurement_units}"|grep -q '~'; then
+            value=$(echo "${measurement_units}"|cut -d~ -f1)
         else
             value=${measurement_units}
         fi
@@ -83,7 +86,7 @@ statistic(){
             min=$(f_min "$min" "$value")
         else
             if [ "X${old_key}" != "X" ]; then
-                if [ $count -ge 4 ]; then
+                if [ "${count}" -ge 4 ]; then
                     average=$(echo "${total},${max},${min},$count"|awk -F, '{printf "%.2f",($1-$2-$3)/($4-2);}')
                 else
                     average=$(echo "${total},$count"|awk -F, '{printf "%.2f",$1/$2;}')
@@ -99,13 +102,13 @@ statistic(){
             min="${value}"
             old_key="${new_key}"
             count=1
-            if echo ${measurement_units}|grep -q '~'; then
-                units=$(echo ${measurement_units}|cut -d~ -f2)
+            if echo "${measurement_units}"|grep -q '~'; then
+                units=$(echo "${measurement_units}"|cut -d~ -f2)
             else
                 units=""
             fi
         fi
-    done
+    done < "${f_data}.sort"
     if [ "X${new_key}" != "X" ]; then
         if [ $count -ge 4 ]; then
             average=$(echo "${total},${max},${min},$count"|awk -F, '{printf "%.2f",($1-$2-$3)/($4-2);}')
@@ -133,17 +136,17 @@ statistic(){
 ##    G_VERBOSE_OUTPUT: when this environment variant is set to "TRUE", and only it is TRUE,
 ##         the verbose informain about the result will be outputed
 output_test_result(){
-    local test_name=$1
-    local result=$2
-    local measurement=$3
-    local units=$4
+    test_name=$1
+    result=$2
+    measurement=$3
+    units=$4
 
     if [ -z "${test_name}" ] || [ -z "$result" ]; then
         return
     fi
-    local output=""
-    local lava_paras=""
-    local output_csv=""
+    output=""
+    lava_paras=""
+    output_csv=""
     if [ -z "$units" ]; then
         units="points"
     fi
@@ -160,8 +163,9 @@ output_test_result(){
         echo "${output}"
     fi
 
-    local cmd="lava-test-case"
-    if [ -n "$(which $cmd)" ];then
+    cmd="lava-test-case"
+    if [ "X${G_RESULT_NOT_RECORD}" = "XFALSE" ] && [ -n "$(which $cmd)" ];then
+        # shellcheck disable=SC2086
         $cmd ${lava_paras}
     elif [ "X${G_VERBOSE_OUTPUT}" = "XTRUE" ];then
         echo "$cmd ${lava_paras}"
@@ -174,17 +178,18 @@ output_test_result(){
 }
 
 func_print_usage_common(){
-    echo "$(basename $0) [--record-csv TRUE|others] [--loop-count LOOP_COUNT]"
+    script_name=$(basename "$0")
+    echo "${script_name} [--record-csv TRUE|others] [--loop-count LOOP_COUNT]"
     echo "     --record-csv: specify if record the result in csv format in file ${F_RAW_DATA_CSV}"
     echo "                   Only record the file when TRUE is specified."
     echo "     --loop-count: specify the number that how many times should be run for each application to get the average result, default is 12"
     echo "     --verbose-output: output the result and lava-test-case command for each test case each time it is run"
-    echo "$(basename $0) [--help|-h]"
+    echo "${script_name} [--help|-h]"
     echo "     print out this usage."
 }
 
 func_parse_parameters_common(){
-    local para_loop_count=""
+    para_loop_count=""
     while [ -n "$1" ]; do
         case "X$1" in
             X--record-csv)
@@ -228,7 +233,7 @@ func_parse_parameters_common(){
     done
 
     if [ -n "${para_loop_count}" ]; then
-        local tmp_str=$(echo ${para_loop_count}|tr -d '[:digit:]')
+        tmp_str=$(echo "${para_loop_count}"|tr -d '[:digit:]')
         if [ -z "${tmp_str}" ]; then
             G_LOOP_COUNT=${para_loop_count}
         else
@@ -264,11 +269,11 @@ run_test(){
     if [ "X${G_RECORD_LOCAL_CSV}" = "XTRUE" ]; then
         [ -f "${F_RAW_DATA_CSV}" ] && rm "${F_RAW_DATA_CSV}"
         [ -f "${F_STATISTIC_DATA_CSV}" ] && rm "${F_STATISTIC_DATA_CSV}"
-        mkdir -p $(dirname ${F_RAW_DATA_CSV})
+        mkdir -p "$(dirname ${F_RAW_DATA_CSV})"
     fi
 
     loop_index=0
-    while [ ${loop_index} -lt ${G_LOOP_COUNT} ]; do
+    while [ "${loop_index}" -lt "${G_LOOP_COUNT}" ]; do
         if [ -n "${var_test_func}" ]; then
             ${var_test_func}
         fi