From 20d85f45e87323731eb7b1ad600d556b4e07fff2 Mon Sep 17 00:00:00 2001 From: shirshkumar Date: Mon, 11 Jun 2018 16:13:01 +0530 Subject: [PATCH] Logging Optimization and time profiling The log generated contained some extra redundan information. Those have been removed and error message has been made more informative. Added error handling for fopen in patch reading case. Time profiling has been enabled with better precision. Change-Id: I4b2d595e5fd63de51a9d569ce4222a738c995f69 Signed-off-by: shirshkumar --- ss_engine/SS_UPI.c | 168 ++++++++++++++++++++++++++++++++++++++--------------- 1 file changed, 120 insertions(+), 48 deletions(-) diff --git a/ss_engine/SS_UPI.c b/ss_engine/SS_UPI.c index 09596cb..43828b5 100755 --- a/ss_engine/SS_UPI.c +++ b/ss_engine/SS_UPI.c @@ -98,6 +98,8 @@ int SS_Do_Memory_Profiling() #ifdef TIME_PROFILING static char ts1[256]; static double ts2; +double t1; +double t2; double fast_tar_get_item_size_time = 0.0; double SS_LoadFile_time = 0.0; double SS_FSBuildNodes_time = 0.0; @@ -1387,9 +1389,7 @@ int SS_FSUpdateFile(int ubFileType, ua_dataSS_t * ua_dataSS, int ulPatchCount, f const char *patch_path) { int ulFileIndex = 1; - char ubPatch[SS_MAX_FILE_PATH] = { - 0 - }; + char ubPatch[SS_MAX_FILE_PATH] = { 0, }; int ulReadCnt = 0; int ulResult = S_SS_SUCCESS; FileInfo source_file; @@ -1403,13 +1403,16 @@ int SS_FSUpdateFile(int ubFileType, ua_dataSS_t * ua_dataSS, int ulPatchCount, f switch (ubFileType) { case DIFFS: { - tar_open(ua_dataSS->update_data->ua_delta_path); + LOGL(LOG_SSENGINE, "DIFFS mode start\n"); #ifdef TIME_PROFILING - get_time_stamp1(); //total time capturing - t1 = atoi(ts1); + get_time_stamp1(); //total time capturing + t1 = atof(ts1); + LOGL(LOG_SSENGINE, "DIFFS mode start time = [%lf]\n", + t1); #endif + tar_open(ua_dataSS->update_data->ua_delta_path); while (pFsNode) { - LOGL(LOG_SSENGINE, "DIFFS update Index: [%d] \n", ulFileIndex++); + //LOGL(LOG_SSENGINE, "DIFFS update Index: [%d] \n", ulFileIndex++); snprintf(ubPatch, SS_MAX_FILE_PATH, "%s%s", patch_path, pFsNode->patch_name); //LOGL(LOG_SSENGINE, "DIFF list --- [File Name %s]\n [Patch Name %s]",pFsNode->file_path, ubPatch); if (pFsNode->data_size > 0) { @@ -1430,8 +1433,8 @@ int SS_FSUpdateFile(int ubFileType, ua_dataSS_t * ua_dataSS, int ulPatchCount, f SS_UpdateDeltaFS(pFsNode->file_old_path, pFsNode->file_new_path, pFsNode->sha1src, pFsNode->sha1trg, pFsNode->data_size); if (ulResult != S_SS_SUCCESS) { - LOGE("FS update Failed Result : [%d], [Item - %s]and size is[%d] Read Count[%d]\n", ulResult, - ubPatch, pFsNode->data_size, ulReadCnt); + LOGE("FS update Failed Result : [%d], [Item - %s]and size is[%d] Read Count[%d], index = [%d]\n", ulResult, + ubPatch, pFsNode->data_size, ulReadCnt, ulFileIndex); tar_close(); SS_SetUpgradeState(E_SS_FSUPDATEFAILED); break; @@ -1442,27 +1445,38 @@ int SS_FSUpdateFile(int ubFileType, ua_dataSS_t * ua_dataSS, int ulPatchCount, f else { ulResult = E_SS_FAILURE; tar_close(); - LOGE("size is invalid\n"); + LOGE("size is invalid, index = [%d]\n", + ulFileIndex); SS_SetUpgradeState(E_SS_FSUPDATEFAILED); break; } + ulFileIndex++; } + LOGL(LOG_SSENGINE, "DIFFS : Total index = [%d]\n", + ulFileIndex - 1); #ifdef TIME_PROFILING get_time_stamp1(); //total time capturing - t2 = atoi(ts1); - LOG("Shirsh time for DIFFS - [%d] \n", (t2 - t1)); + t2 = atof(ts1); + LOGL(LOG_SSENGINE, + "DIFFS mode end time = [%lf], diff = [%lf]\n", t2, + (t2 - t1)); #endif tar_close(); + LOGL(LOG_SSENGINE, "DIFFS mode end\n"); } break; case MOVES: { + LOGL(LOG_SSENGINE, "MOVES mode start\n"); + #ifdef TIME_PROFILING get_time_stamp1(); //total time capturing - t1 = atoi(ts1); + t1 = atof(ts1); + LOGL(LOG_SSENGINE, "MOVES mode start time = [%lf]\n", + t1); #endif while (pFsNode) { - LOGL(LOG_SSENGINE, "MOVES update Index: [%d] \n", ulFileIndex++); + //LOGL(LOG_SSENGINE, "MOVES update Index: [%d] \n", ulFileIndex++); int skip_flag = 0; if (SS_LoadFile(pFsNode->file_old_path, &source_file) == 0) { LOGL(LOG_SSENGINE, "Patch Can be applied\n"); @@ -1501,7 +1515,7 @@ int SS_FSUpdateFile(int ubFileType, ua_dataSS_t * ua_dataSS, int ulPatchCount, f if (skip_flag == 0) { ulResult = SS_MoveFile(pFsNode->file_old_path, pFsNode->file_new_path); if (ulResult != S_SS_SUCCESS) { - LOGE("Move Failed for [%s] to [%s]\n", pFsNode->file_old_path, pFsNode->file_new_path); + LOGE("Move Failed for [%s] to [%s], result = [%d], index = [%d]\n", pFsNode->file_old_path, pFsNode->file_new_path, ulResult, ulFileIndex); SS_SetUpgradeState(ulResult); break; } else { @@ -1532,51 +1546,71 @@ int SS_FSUpdateFile(int ubFileType, ua_dataSS_t * ua_dataSS, int ulPatchCount, f } SS_UpdateUIProgress(ua_dataSS, ulPatchCount, 0); pFsNode = pFsNode->nextnode; + ulFileIndex++; } + LOGL(LOG_SSENGINE, "MOVES : Total index = [%d]\n", + ulFileIndex - 1); #ifdef TIME_PROFILING get_time_stamp1(); //total time capturing - t2 = atoi(ts1); - LOG("Shirsh time for MOVES - [%d] \n", (t2 - t1)); + t2 = atof(ts1); + LOGL(LOG_SSENGINE, + "MOVES mode end time = [%lf], diff = [%lf]\n", t2, + (t2 - t1)); #endif + LOGL(LOG_SSENGINE, "MOVES mode end\n"); } break; case DELETES: { + LOGL(LOG_SSENGINE, "DELETES mode start\n"); + int ulFiletype = 0; #ifdef TIME_PROFILING get_time_stamp1(); //total time capturing - t1 = atoi(ts1); + t1 = atof(ts1); + LOGL(LOG_SSENGINE, "DELETES mode start time = [%lf]\n", + t1); #endif while (pFsNode) { if (pFsNode->type == DELETES) { - LOGL(LOG_SSENGINE, "DELETES update Index: [%d] \n", ulFileIndex++); + //LOGL(LOG_SSENGINE, "DELETES update Index: [%d] \n", ulFileIndex++); SS_GetFileType(pFsNode->file_old_path, (enumFileType *) & ulFiletype); if (ulFiletype == 2) //FT_FOLDER ulResult = SS_DeleteFolder(pFsNode->file_old_path); else ulResult = SS_DeleteFile(pFsNode->file_old_path); if (ulResult != S_SS_SUCCESS) { - LOGE("Delete Failed\n"); + LOGE("Delete Failed, result = [%d], index = [%d]\n", ulResult, ulFileIndex); SS_SetUpgradeState(ulResult); break; } + ulFileIndex++; } SS_UpdateUIProgress(ua_dataSS, ulPatchCount, 0); pFsNode = pFsNode->nextnode; } + LOGL(LOG_SSENGINE, "DELETES : Total index = [%d]\n", + ulFileIndex - 1); #ifdef TIME_PROFILING get_time_stamp1(); //total time capturing - t2 = atoi(ts1); - LOG("Shirsh time for DELETES - [%d] \n", (t2 - t1)); + t2 = atof(ts1); + LOGL(LOG_SSENGINE, + "DELETES mode end time = [%lf], diff = [%lf]\n", + t2, (t2 - t1)); #endif + LOGL(LOG_SSENGINE, "DELETES mode end\n"); } break; case DELETE_END: { + LOGL(LOG_SSENGINE, "DELETE_END mode start\n"); + int ulFiletype = 0; #ifdef TIME_PROFILING get_time_stamp1(); //total time capturing - t1 = atoi(ts1); + t1 = atof(ts1); + LOGL(LOG_SSENGINE, + "DELETE_END mode start time = [%lf]\n", t1); #endif while (pFsNode) { if (pFsNode->type == DELETE_END) { @@ -1587,26 +1621,36 @@ int SS_FSUpdateFile(int ubFileType, ua_dataSS_t * ua_dataSS, int ulPatchCount, f else ulResult = SS_DeleteFile(pFsNode->file_old_path); if (ulResult != S_SS_SUCCESS) { - LOGE("Delete Failed\n"); + LOGE("Delete Failed, result = [%d], index = [%d]\n", ulResult, ulFileIndex); SS_SetUpgradeState(ulResult); break; } + ulFileIndex++; } pFsNode = pFsNode->nextnode; } + LOGL(LOG_SSENGINE, "DELETE_END : Total index = [%d]\n", + ulFileIndex - 1); #ifdef TIME_PROFILING - get_time_stamp1(); //total time capturing - t2 = atoi(ts1); - LOG("Shirsh time for DELETE_END - [%d] \n", (t2 - t1)); + get_time_stamp1(); //total time capturing + t2 = atof(ts1); + LOGL(LOG_SSENGINE, + "DELETE_END mode start time = [%lf], diff = [%lf]\n", + t2, (t2 - t1)); #endif + LOGL(LOG_SSENGINE, "DELETE_END mode end\n"); } break; case NEWFILES: { + LOGL(LOG_SSENGINE, "NEWFILES mode start\n"); + #ifdef TIME_PROFILING - get_time_stamp1(); //total time capturing - t1 = atoi(ts1); + get_time_stamp1(); //total time capturing + t1 = atof(ts1); + LOGL(LOG_SSENGINE, "NEWFILES mode start time = [%lf]\n", + t1); #endif LOGL(LOG_SSENGINE, "Starting New file upgrade for [%s]\n", patch_path); if (tar_extract_file(ua_dataSS->update_data->ua_delta_path, (char *)patch_path, SS_NEW_COMPRESSED_FILE) >= @@ -1619,61 +1663,78 @@ int SS_FSUpdateFile(int ubFileType, ua_dataSS_t * ua_dataSS, int ulPatchCount, f LOGL(LOG_SSENGINE, "tar extraction error for %s\n", ua_dataSS->parti_info->ua_parti_name); SS_DeleteFile(SS_NEW_COMPRESSED_FILE); #ifdef TIME_PROFILING - get_time_stamp1(); //total time capturing - t2 = atoi(ts1); - LOG("Shirsh time for NEWFILES - [%d] \n", (t2 - t1)); + get_time_stamp1(); //total time capturing + t2 = atof(ts1); + LOGL(LOG_SSENGINE, + "NEWFILES mode end time = [%lf], diff = [%lf]\n", + t2, (t2 - t1)); #endif + LOGL(LOG_SSENGINE, "NEWFILES mode end\n"); } break; case SYMDIFFS: { + LOGL(LOG_SSENGINE, "SYMDIFFS mode start\n"); + #ifdef TIME_PROFILING - get_time_stamp1(); //total time capturing - t1 = atoi(ts1); + get_time_stamp1(); //total time capturing + t1 = atof(ts1); + LOGL(LOG_SSENGINE, "SYMDIFFS mode start time = [%lf]\n", + t1); #endif while (pFsNode) { - LOGL(LOG_SSENGINE, "SYMDIFFS update Index: [%d] \n", ulFileIndex++); + //LOGL(LOG_SSENGINE, "SYMDIFFS update Index: [%d] \n", ulFileIndex++); //LOG("Sym Diff file paths: [Linkname - %s] [reference file name- %s][]\n", pFsNode->file_path,pFsNode->patch_name); ulResult = SS_Unlink(pFsNode->file_old_path); if (ulResult == S_SS_SUCCESS) { ulResult = SS_Link(NULL, pFsNode->file_new_path, pFsNode->patch_name); if (ulResult != S_SS_SUCCESS) { - LOGE("SS_Link Failed, Linkname:[%s], reference file name:[%s]\n", - pFsNode->file_new_path, pFsNode->patch_name); + LOGE("SS_Link Failed, Linkname:[%s], reference file name, index = [%d]:[%s]\n", + pFsNode->file_new_path, pFsNode->patch_name, ulFileIndex); } } else { - LOGE("SS_Unlink Failed\n"); + LOGE("Unlink Failed, result = [%d], index = [%d]\n", ulResult, ulFileIndex); SS_SetUpgradeState(E_SS_FSUPDATEFAILED); break; } SS_UpdateUIProgress(ua_dataSS, ulPatchCount, 0); pFsNode = pFsNode->nextnode; + ulFileIndex++; } + LOGL(LOG_SSENGINE, "SYMDIFFS : Total index = [%d]\n", + ulFileIndex - 1); #ifdef TIME_PROFILING - get_time_stamp1(); //total time capturing - t2 = atoi(ts1); - LOG("Shirsh time for SYMDIFFS - [%d] \n", (t2 - t1)); + get_time_stamp1(); //total time capturing + t2 = atof(ts1); + LOGL(LOG_SSENGINE, + "SYMDIFFS mode end time = [%lf], diff = [%lf]\n", + t2, (t2 - t1)); #endif + LOGL(LOG_SSENGINE, "SYMDIFFS mode end\n"); } break; case SYMNEWFILES: { + LOGL(LOG_SSENGINE, "SYMNEWFILES mode start\n"); + fs_params *head_node; int retry_count = 0, do_retry = 0; #ifdef TIME_PROFILING - get_time_stamp1(); //total time capturing - t1 = atoi(ts1); + get_time_stamp1(); //total time capturing + t1 = atof(ts1); + LOGL(LOG_SSENGINE, + "SYMNEWFILES mode start time = [%lf]\n", t1); #endif SYMLINK_CREATE: head_node = pFsNode; while (head_node) { - LOGL(LOG_SSENGINE, "SYMNEWS update Index: [%d] \n", ulFileIndex++); + //LOGL(LOG_SSENGINE, "SYMNEWS update Index: [%d] \n", ulFileIndex++); snprintf(ubPatch, SS_MAX_FILE_PATH, "%s%s%s", patch_path, "/", head_node->patch_name); LOGL(LOG_SSENGINE, "Sym New file paths: [Linkname - %s] [reference file name- %s][]\n", head_node->file_old_path, head_node->patch_name); ulResult = SS_Link(NULL, head_node->file_old_path, head_node->patch_name); if (ulResult == E_SS_FAILURE) { - LOGE("Link Failed\n"); + LOGE("Link Failed, result = [%d], index = [%d]\n", ulResult, ulFileIndex); SS_SetUpgradeState(E_SS_FSUPDATEFAILED); break; } else if (ulResult == ENOENT) { //to handle cases where new symlink points to a new symlink yet to be created @@ -1684,7 +1745,10 @@ int SS_FSUpdateFile(int ubFileType, ua_dataSS_t * ua_dataSS, int ulPatchCount, f } SS_UpdateUIProgress(ua_dataSS, ulPatchCount, 0); head_node = head_node->nextnode; + ulFileIndex++; } + LOGL(LOG_SSENGINE, "SYMNEWFILES : Total index = [%d]\n", + ulFileIndex - 1); if (do_retry && (retry_count < 4)) { retry_count++; ulFileIndex = 0; @@ -1696,10 +1760,13 @@ int SS_FSUpdateFile(int ubFileType, ua_dataSS_t * ua_dataSS, int ulPatchCount, f break; } #ifdef TIME_PROFILING - get_time_stamp1(); //total time capturing - t2 = atoi(ts1); - LOG("Shirsh time for SYMNEWS - [%d] \n", (t2 - t1)); + get_time_stamp1(); //total time capturing + t2 = atof(ts1); + LOGL(LOG_SSENGINE, + "SYMNEWFILES mode end time = [%lf], diff = [%lf]\n", + t2, (t2 - t1)); #endif + LOGL(LOG_SSENGINE, "SYMNEWFILES mode end\n"); } break; default: @@ -2265,6 +2332,11 @@ int SS_IMGUpdatemain(ua_dataSS_t * ua_dataSS, int update_type) //SS_FSUpdatePar char buf[14] = { 0, }; //to store zImage-delta magic keyword ssize_t bytes_read; fp = fopen(SS_PATCHFILE_SOURCE, "r"); + if (fp == NULL) { + LOGE("Failed to open patch file Error:[%s]\n", strerror(errno)); + SS_SetUpgradeState(E_SS_FSFAILEDTOOPENPATCHINFO); + return E_SS_FAILURE; + } bytes_read = fread(buf, 1, 13, fp); //error check not required as any delta corruption will be caught in SS_UpdateDeltaIMG if (bytes_read != 13) LOGL(LOG_SSENGINE, "short read of \"%s\" (%ld bytes of %ld)\n", SS_PATCHFILE_SOURCE, (long)bytes_read, (long)13); -- 2.7.4