summaryrefslogtreecommitdiff
path: root/automated
diff options
context:
space:
mode:
authorChase Qi <chase.qi@linaro.org>2017-03-28 16:32:33 +0800
committerMilosz Wasilewski <milosz.wasilewski@linaro.org>2017-04-11 10:09:10 +0000
commita6c4f8865c27b8eaf41e631e30bdb334142bf863 (patch)
treee347ab2ab61023b122e8699260977a2b17008a2b /automated
parent50842e55a4a8bd9490120b40fe285de27cc64441 (diff)
automated: android: migrate boottime2
Migrated from android/boottime2. Most of the code in device-script.sh remain as it was. To keep consistence and cope with v2 structure: * Removed lava-specific steps from test script. * Copied the required functions from android/script/common.sh to device-script.sh Change-Id: I3560fe5dd863a1d32ced14806e852170494ea293 Signed-off-by: Chase Qi <chase.qi@linaro.org>
Diffstat (limited to 'automated')
-rwxr-xr-xautomated/android/boottime/boottime.sh41
-rw-r--r--automated/android/boottime/boottime.yaml37
-rwxr-xr-xautomated/android/boottime/device-script.sh498
3 files changed, 576 insertions, 0 deletions
diff --git a/automated/android/boottime/boottime.sh b/automated/android/boottime/boottime.sh
new file mode 100755
index 0000000..b67e4ff
--- /dev/null
+++ b/automated/android/boottime/boottime.sh
@@ -0,0 +1,41 @@
+#!/bin/sh -e
+# shellcheck disable=SC1091
+
+ANDROID_SERIAL=""
+BOOT_TIMEOUT="300"
+OPERATION="COLLECT"
+COLLECT_NO="1"
+OUTPUT="$(pwd)/output"
+
+. ../../lib/sh-test-lib
+. ../../lib/android-test-lib
+
+usage() {
+ echo "Usage: $0 [-s <android_serial>] [-t <boot_timeout>] [-o <COLLECT|ANALYZE>] [-n <collect_no>]" 1>&2
+ exit 1
+}
+
+while getopts ":s:t:o:n:" o; do
+ case "$o" in
+ s) ANDROID_SERIAL="${OPTARG}" ;;
+ t) BOOT_TIMEOUT="${OPTARG}" ;;
+ o) OPERATION="${OPTARG}" ;;
+ n) COLLECT_NO="${OPTARG}" ;;
+ *) usage ;;
+ esac
+done
+
+initialize_adb
+wait_boot_completed "${BOOT_TIMEOUT}"
+create_out_dir "${OUTPUT}"
+
+adb_push "./device-script.sh" "/data/local/tmp/"
+info_msg "device-${ANDROID_SERIAL}: About to run boottime ${OPERATION} ${COLLECT_NO}..."
+adb shell "/data/local/tmp/device-script.sh ${OPERATION} ${COLLECT_NO}" \
+ | tee "${OUTPUT}/device-stdout.log"
+
+adb_pull "/data/local/tmp/boottime/" "${OUTPUT}/device-boottime"
+cp "${OUTPUT}/device-boottime/result.txt" "${OUTPUT}/"
+if [ "${OPERATION}" = "ANALYZE" ]; then
+ adb_pull "/data/local/tmp/boottime.tgz" "${OUTPUT}"
+fi
diff --git a/automated/android/boottime/boottime.yaml b/automated/android/boottime/boottime.yaml
new file mode 100644
index 0000000..51bc5df
--- /dev/null
+++ b/automated/android/boottime/boottime.yaml
@@ -0,0 +1,37 @@
+metadata:
+ name: boottime
+ 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
+ - chase.qi@linaro.org
+ os:
+ - android
+ scope:
+ - performance
+ devices:
+ - juno
+ - hi6220-hikey
+
+params:
+ # Specify device serial no. when more than one device connected.
+ ANDROID_SERIAL: ""
+ # Specify timeout in seconds for wait_boot_completed.
+ BOOT_TIMEOUT: "300"
+ # Available operations: COLLECT or ANALYZE
+ OPERATION: "COLLECT"
+ COLLECT_NO: "1"
+ # Specify url and token for file uploading.
+ URL: "https://archive.validation.linaro.org/artifacts/team/qa/"
+ TOKEN: "4373c97b474497dbd12373689d7d492e"
+
+run:
+ steps:
+ - cd ./automated/android/boottime
+ - ./boottime.sh -s "${ANDROID_SERIAL}" -t "${BOOT_TIMEOUT}" -o "${OPERATION}" -n "${COLLECT_NO}"
+ - if [ "${OPERATION}" = "ANALYZE" ]; then ../../utils/upload-to-artifactorial.sh -a "output/boottime.tgz" -u "${URL}" -t "${TOKEN}"; fi
+ - ../../utils/send-to-lava.sh ./output/result.txt
diff --git a/automated/android/boottime/device-script.sh b/automated/android/boottime/device-script.sh
new file mode 100755
index 0000000..90e1736
--- /dev/null
+++ b/automated/android/boottime/device-script.sh
@@ -0,0 +1,498 @@
+#!/system/bin/sh
+##############################################################################
+## Description about this boot time measuring script ####
+##############################################################################
+## This script will be run on the device, it has following 2 functions:
+## 1. collecting the dmesg log and logcat information, and save them under
+## /data/local/tmp/boottime
+## directory in the name for following format:
+## logcat_all_${COLLECT_NO}.log :
+## collected via command "logcat -d -v time *:V"
+## logcat_events_${COLLECT_NO}.log:
+## collected via command "logcat -d -b events -v time"
+## dmesg_${COLLECT_NO}.log:
+## collected via command "dmesg"
+## when this script is run as following:
+## ./android/scripts/boottime2.sh COLLECT ${COLLECT_NO}
+##
+## 2. analyzing boottime inforamtion from the collected log information
+## when this script is run as following:
+## ./android/scripts/boottime2.sh ANALYZE ${COLLECT_NO}
+##
+## it will get the average of multiple iterations for the boot time,
+## so that to get more stable and accurate boot time information:
+##
+## iterations < 4: the average will be calculated with all data
+## iterations >= 4: the average will be calculated with maximum
+## and minimum will be removed
+## For each iteration, it will get following boot time information:
+## (assuming kernel started at 0 timestamp in this script)
+##
+## TOTAL_BOOT_TIME:
+## the sum of KERNEL_BOOT_TIME and ANDROID_BOOT_TIME
+##
+## KERNEL_BOOT_TIME:
+## from kernel started to line "Freeing unused kernel memory" printed,
+## it does not include kernel loading and uncompression part done
+## by bootloader or kernel itself
+##
+## ANDROID_BOOT_TIME:
+## the sum of INIT_TO_SURFACEFLINGER_START_TIME and SURFACEFLINGER_BOOT_TIME
+##
+## SURFACEFLINGER_BOOT_TIME: the time information is gotten from the line
+## contains "Boot is finished" like following in logcat:
+## 1-01 00:00:27.158 I/SurfaceFlinger( 1835): Boot is finished (13795 ms)
+## the time here means the time from surfaceflinger service started
+## to the time boot animation finished.
+## it does not include the time from init start to the time
+## surfaceflinger service started
+##
+## 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
+##
+## INIT_TO_SURFACEFLINGER_START_TIME:
+## from the time "Freeing unused kernel memory" printed in dmesg
+## to the time "init: Starting service 'surfaceflinger'..." is printed
+##
+## FS_MOUNT_TIME:
+## from the time "Freeing unused kernel memory:" printed
+## to the time "init: Starting service 'logd'..." printed.
+##
+## FS_MOUNT_DURATION:
+## from the line "init: /dev/hw_random not found" printed
+## to the time "init: Starting service 'logd'..." printed
+##
+## BOOTANIM_TIME:
+## from the time "init: Starting service 'bootanim'..." printed
+## to the time "init: Service 'bootanim'.* exited with status" printed
+##
+## ANDROID_SERVICE_START_TIME:
+## from the time kernel started to the time healthd service started
+##
+## ANDROID_UI_SHOWN:
+## time from freeing unused kernel memory to the time
+## when UI is shown on display
+##############################################################################
+
+local_file_path="$0"
+local_file_parent=$(dirname "${local_file_path}")
+local_file_parent=$(cd "${local_file_parent}"||exit; pwd)
+
+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"
+RESULT_FILE="${dir_boottime_data}/result.txt"
+
+## Copied from android/scripts/common.sh.
+G_RECORD_LOCAL_CSV=TRUE
+G_VERBOSE_OUTPUT=FALSE
+G_RESULT_NOT_RECORD=FALSE
+
+## Description:
+## output the max value of the passed 2 parameters
+## Usage:
+## f_max "${val1}" "${val2}"
+## Example:
+## max=$(f_max "1.5" "2.0")
+f_max(){
+ 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}'
+}
+
+## Description:
+## output the min value of the passed 2 parameters
+## Usage:
+## f_min "${val1}" "${val2}"
+## Example:
+## min=$(f_min "1.5" "2.0")
+f_min(){
+ 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}'
+}
+
+## Description:
+## calculate the average value for specified csv file.
+## The first field of that csv file should be the key/name of that line,
+## Lines have the same key should be together.
+## Usage:
+## statistic "${csv_file_path}" "${file_number}"
+## Example:
+## statistic "$f_res_starttime" 2
+## Note:
+## 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(){
+ f_data=$1
+ if ! [ -f "$f_data" ]; then
+ return
+ fi
+ field_no=$2
+ if [ -z "$field_no" ]; then
+ field_no=2
+ fi
+ 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)
+ 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
+
+ if [ "X${new_key}" = "X${old_key}" ]; then
+ total=$(echo "${total},${value}"|awk -F, '{printf "%.2f",$1+$2;}')
+ count=$(echo "${count},1"|awk -F, '{printf $1+$2;}')
+ max=$(f_max "$max" "$value")
+ min=$(f_min "$min" "$value")
+ else
+ if [ "X${old_key}" != "X" ]; 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;}')
+ fi
+ if [ -z "${units}" ]; then
+ echo "${old_key}=${average}"
+ else
+ echo "${old_key}=${average},${units}"
+ fi
+ fi
+ total="${value}"
+ max="${value}"
+ min="${value}"
+ old_key="${new_key}"
+ count=1
+ if echo "${measurement_units}"|grep -q '~'; then
+ units=$(echo "${measurement_units}"|cut -d~ -f2)
+ else
+ units=""
+ fi
+ fi
+ 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);}')
+ else
+ average=$(echo "${total},$count"|awk -F, '{printf "%.2f",$1/$2;}')
+ fi
+ if [ -z "${units}" ]; then
+ echo "${new_key}=${average}"
+ else
+ echo "${new_key}=${average},${units}"
+ fi
+ fi
+ rm "${f_data}.sort"
+}
+
+## Description:
+## output the test result to console and add for lava-test-shell,
+## also write into one csv file for comparing manually
+## Usage:
+## output_test_result $test_name $result [ $measurement [ $units ] ]
+## Note:
+## G_RECORD_LOCAL_CSV: when this environment variant is set to "TRUE",
+## the result will be recorded in a csv file in the following path:
+## rawdata/final_result.csv
+## 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(){
+ test_name=$1
+ result=$2
+ measurement=$3
+ units=$4
+
+ if [ -z "${test_name}" ] || [ -z "$result" ]; then
+ return
+ fi
+ output=""
+ lava_paras=""
+ output_csv=""
+ if [ -z "$units" ]; then
+ units="points"
+ fi
+ if [ -z "${measurement}" ]; then
+ output="${test_name}=${result}"
+ lava_paras="${test_name} ${result}"
+ else
+ output="${test_name}=${measurement} ${units}"
+ lava_paras="${test_name} ${result} ${measurement} ${units}"
+ output_csv="${test_name},${measurement} ${units}"
+ fi
+
+ echo "${lava_paras}" | tee -a "${RESULT_FILE}"
+
+ if [ "X${G_VERBOSE_OUTPUT}" = "XTRUE" ];then
+ echo "${output}"
+ fi
+
+ if [ "X${G_RECORD_LOCAL_CSV}" = "XTRUE" ]; then
+ if [ -n "${output_csv}" ]; then
+ echo "${output_csv}">>${F_RAW_DATA_CSV}
+ fi
+ fi
+}
+
+# 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
+}
+
+# logcat_all line example
+# 01-01 00:00:26.313 I/SurfaceFlinger( 1850): Boot is finished (11570 ms)
+getTimeStampFromLogcat(){
+ key=$1
+ if [ -z "${key}" ]; then
+ return
+ fi
+
+ key_line=$(grep "${key}" "${LOG_LOGCAT_ALL}")
+ if [ -n "${key_line}" ]; then
+ timestamp_sec=$(echo "${key_line}"|awk '{print $2}' | awk -F ":" '{print $3}')
+ timestamp_min=$(echo "${key_line}"|awk '{print $2}' | awk -F ":" '{print $2}')
+ timestamp=$(echo "${timestamp_sec} ${timestamp_min}" | awk '{printf "%.3f",$1 + $2 * 60;}')
+ 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
+ KERNEL_BOOT_TIME=$(echo "${CONSOLE_SECONDS_END} ${CONSOLE_SECONDS_START} - p" | dc)
+ output_test_result "KERNEL_BOOT_TIME" "pass" "${KERNEL_BOOT_TIME}" "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"
+ 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"
+ fi
+
+ POINT_SERVICE_BOOTANIM_START=$(getTime "init: Starting service 'bootanim'..."|tail -n1)
+ POINT_SERVICE_BOOTANIM_END=$(getTime "init: Service 'bootanim'.* exited with status"|tail -n1)
+ 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"
+ 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"
+ fi
+
+ POINT_SURFACEFLINGER_BOOT=$(getTimeStampFromLogcat "Boot is finished")
+ POINT_SURFACEFLINGER_START=$(getTimeStampFromLogcat "SurfaceFlinger is starting")
+ POINT_LAUNCHER_DISPLAYED=$(getTimeStampFromLogcat "Displayed com.android.launcher")
+
+ ## 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",
+ ## use the last one line, and report the case later after checked all the logs
+ SURFACEFLINGER_BOOT_TIME_INFO=$(grep "Boot is finished" "${LOG_LOGCAT_ALL}"|tail -n1)
+ if [ -n "${SURFACEFLINGER_BOOT_TIME_INFO}" ]; then
+ while echo "${SURFACEFLINGER_BOOT_TIME_INFO}"|grep -q "("; do
+ SURFACEFLINGER_BOOT_TIME_INFO=$(echo "${SURFACEFLINGER_BOOT_TIME_INFO}"|cut -d\( -f2-)
+ done
+ SURFACEFLINGER_BOOT_TIME_MS=$(echo "${SURFACEFLINGER_BOOT_TIME_INFO}"|cut -d\ -f1)
+ SURFACEFLINGER_BOOT_TIME=$(echo "${SURFACEFLINGER_BOOT_TIME_MS}" | awk '{printf "%.3f",$1/1000;}')
+ output_test_result "SURFACEFLINGER_BOOT_TIME" "pass" "${SURFACEFLINGER_BOOT_TIME}" "s"
+
+ if [ ! -z "${POINT_SURFACEFLINGER_BOOT}" ] && [ ! -z "${POINT_LAUNCHER_DISPLAYED}" ] && [ ! -z "${POINT_SURFACEFLINGER_START}" ] && [ ! -z "${INIT_TO_SURFACEFLINGER_START_TIME}" ]; then
+
+ min=$(echo "${POINT_LAUNCHER_DISPLAYED} ${POINT_SURFACEFLINGER_BOOT}" | awk '{if ($1 < $2) printf $1; else print $2}')
+
+ ## In case timestamp of "Boot is finished" is smaller than timestamp of "Displayed com.android.launcher" we calculate ANDROID_UI_SHOWN as "Boot is finished" time minus difference
+ ## between two timestamps plus INIT_TO_SURFACEFLINGER_START_TIME
+ if [ "${min}" = "${POINT_SURFACEFLINGER_BOOT}" ]; then
+ ANDROID_UI_SHOWN=$(echo "${POINT_SURFACEFLINGER_BOOT} ${POINT_SURFACEFLINGER_START} ${POINT_SURFACEFLINGER_BOOT} ${POINT_LAUNCHER_DISPLAYED} ${INIT_TO_SURFACEFLINGER_START_TIME}" | awk '{printf "%.3f",$1 - $2 + $4 - $3 + $5;}')
+ ## I case timestamp of "Boot is finished" is greater than timestamp of "Displayed com.android.launcher" we use "Boot is finished" time plus INIT_TO_SURFACEFLINGER_START_TIME
+ ## as ANDROID_UI_SHOWN
+ else
+ ANDROID_UI_SHOWN=$(echo "${POINT_SURFACEFLINGER_BOOT} ${POINT_SURFACEFLINGER_START} ${INIT_TO_SURFACEFLINGER_START_TIME}" | awk '{printf "%.3f",$1 - $2 + $3;}')
+ fi
+ output_test_result "ANDROID_UI_SHOWN" "pass" "${ANDROID_UI_SHOWN}" "s"
+ fi
+ fi
+
+
+ if [ ! -z "${INIT_TO_SURFACEFLINGER_START_TIME}" ] && [ ! -z "${SURFACEFLINGER_BOOT_TIME}" ] ; then
+ ANDROID_BOOT_TIME=$(echo "${INIT_TO_SURFACEFLINGER_START_TIME} ${SURFACEFLINGER_BOOT_TIME}" | awk '{printf "%.3f",$1 + $2;}')
+ 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"
+ fi
+
+ if [ ! -z "${KERNEL_BOOT_TIME}" ] && [ ! -z "${ANDROID_BOOT_TIME}" ] ; then
+ TOTAL_SECONDS=$(echo "${KERNEL_BOOT_TIME} ${ANDROID_BOOT_TIME}" | awk '{printf "%.3f",$1 + $2;}')
+ output_test_result "TOTAL_BOOT_TIME" "pass" "${TOTAL_SECONDS}" "s"
+ fi
+}
+
+OPERATION=$1
+rm -rf "${RESULT_FILE}"
+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
+ ## Check if there is any case that the surfaceflinger service
+ ## was started several times
+ i=1
+ service_started_once=true
+ no_boot_timeout_force_display=true
+ while ${service_started_once}; do
+ if [ $i -gt "$count" ]; then
+ break
+ fi
+ ## check the existence of "Boot is finished"
+ LOG_LOGCAT_ALL="${dir_boottime_data}/logcat_all_${i}.log"
+ android_boottime_lines=$(grep -c "Boot is finished" "${LOG_LOGCAT_ALL}")
+ if [ "${android_boottime_lines}" -ne 1 ]; then
+ echo "There are ${android_boottime_lines} existences of 'Boot is finished' in file: ${LOG_LOGCAT_ALL}"
+ echo "Please check the status first"
+ service_started_once=false
+ fi
+
+ if grep -q "BOOT TIMEOUT: forcing display enabled" "${LOG_LOGCAT_ALL}"; then
+ no_boot_timeout_force_display=false
+ echo "There are boot timeout problem in file: ${LOG_LOGCAT_ALL}"
+ echo "Please check the status first"
+ break
+ fi
+
+ LOG_DMESG="${dir_boottime_data}/dmesg_${i}.log"
+ ## check the service of bootanim
+ bootanim_lines=$(grep -c "init: Service 'bootanim'.* exited with status" "${LOG_DMESG}")
+ if [ "${bootanim_lines}" -ne 1 ]; then
+ echo "bootanim service seems to be started more than once in file: ${LOG_DMESG}"
+ echo "Please check the status first"
+ service_started_once=false
+ fi
+ i=$((i+1))
+ done
+
+ if ! ${no_boot_timeout_force_display}; then
+ output_test_result "NO_BOOT_TIMEOUT_FORCE_DISPLAY" "fail"
+ fi
+ if ! ${service_started_once}; then
+ output_test_result "SERVICE_STARTED_ONCE" "fail"
+ fi
+
+ if ${no_boot_timeout_force_display} && ${service_started_once}; then
+ no_checking_problem=true
+ else
+ no_checking_problem=false
+ fi
+
+ if ${no_checking_problem}; then
+ 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
+
+ output_test_result "SERVICE_STARTED_ONCE" "pass"
+ fi
+
+ # set again for following output_test_result
+ G_RECORD_LOCAL_CSV=FALSE
+ cd ${local_tmp}|| exit 1
+ tar -czvf boottime.tgz boottime
+ 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