[log-analysis] Adds subsecond timing to MGM logs

continuousintegration/log_analysis/CI/get_times.sh

@@ -44,12 +44,12 @@ get_mgm_times()
 {
   TMP_RESULTS=$(grep -m7 "^$1 " xrdmgm-events.log)
 
-  echo -e "${TMP_RESULTS}" | check_results 7
+  echo -e "${TMP_RESULTS}" | check_results 6
   [ $? -ne 0 ] && TMP_RESULTS=$(grep "^$1 " xrdmgm-events.log)
 
   TIME_MGM_CREATE=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CRE" | cut -d' ' -f3)
   TIME_MGM_ACOMMIT=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 ACO" | cut -d' ' -f3)
-  TIME_MGM_CLOSEW=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CLO" | cut -d' ' -f3)
+#  TIME_MGM_CLOSEW=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CLO" | cut -d' ' -f3)
   TIME_MGM_ARCHIVED=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 ARC" | cut -d' ' -f3)
   TIME_MGM_PREPARE=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 PRE" | cut -d' ' -f3)
   TIME_MGM_RCOMMIT=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 RCO" | cut -d' ' -f3)
@@ -113,7 +113,7 @@ get_times()
   echo -n "${TIME_MGM_CREATE},"
   echo -n "${TIME_FE_CREATE},"
   echo -n "${TIME_MGM_ACOMMIT},"
-  echo -n "${TIME_MGM_CLOSEW},"
+#  echo -n "${TIME_MGM_CLOSEW},"
   echo -n "${TIME_FE_CLOSEW},"
   echo -n "${TIME_TS_ARCHIVE_POP},"
   echo -n "${TIME_TS_ARCHIVE_TASKS},"
@@ -147,7 +147,7 @@ FILE_NUM_END=$(wc -l filenameToLogIds.txt | cut -d' ' -f1)
 echoc $LT_BLUE "Creating CSV from events..."
 
 # Print CSV header
-echo -n "Archive File ID,Disk File ID,MGM CREATE,FE CREATE,MGM commit,MGM CLOSEW,FE CLOSEW,"
+echo -n "Archive File ID,Disk File ID,MGM CREATE,FE CREATE,MGM commit,FE CLOSEW,"
 echo -n "TS Archive Pop,TS Archive Tasks,TS Archive Open,TS Archive Read,TS Archive Done,"
 echo -n "TS Archive Report,MGM ARCHIVED,MGM PREPARE,FE PREPARE,TS Retrieve Pop,TS Retrieve Task,"
 echo -n "TS Retrieve Tasks,TS Retrieve Position,TS Retrieve Read,TS Retrieve Open,TS Retrieve Done,"

continuousintegration/log_analysis/CI/postprocess.sh

@@ -38,7 +38,7 @@ convert_abs_rel()
   awk 'BEGIN { FS=","; SKIPHEADER=1; }
     function rel(arg1, arg2) { return arg2-arg1; }
     SKIPHEADER==1 {
-      printf "Archive File ID,Disk File ID,FE CREATE,MGM commit,MGM CLOSEW,TS Archive Pop,TS Archive Tasks,"
+      printf "Archive File ID,Disk File ID,FE CREATE,MGM commit,FE CLOSEW,TS Archive Pop,TS Archive Tasks,"
       printf "TS Archive Open,TS Archive Read,TS Archive Done,TS Archive Report,MGM ARCHIVED,FE PREPARE,"
       printf "TS Retrieve Pop,TS Retrieve Task,TS Retrieve Tasks,TS Retrieve Position,TS Retrieve Read,"
       printf "TS Retrieve Open,TS Retrieve Done,MGM commit,MGM RETRIEVED\n"
@@ -50,33 +50,31 @@ convert_abs_rel()
       TIME_MGM_CREATE=$3
       TIME_FE_CREATE=$4
       TIME_MGM_ACOMMIT=$5
-      TIME_MGM_CLOSEW=$6
-      TIME_FE_CLOSEW=$7
-      TIME_TS_ARCHIVE_POP=$8
-      TIME_TS_ARCHIVE_TASKS=$9
-      TIME_TS_ARCHIVE_OPEN=$10
-      TIME_TS_ARCHIVE_READ=$11
-      TIME_TS_ARCHIVE_DONE=$12
-      TIME_TS_ARCHIVE_REPORT=$13
-      TIME_MGM_ARCHIVED=$14
-      TIME_MGM_PREPARE=$15
-      TIME_FE_PREPARE=$16
-      TIME_TS_RETRIEVE_POP=$17
-      TIME_TS_RETRIEVE_TASK=$18
-      TIME_TS_RETRIEVE_TASKS=$19
-      TIME_TS_RETRIEVE_POSITION=$20
-      TIME_TS_RETRIEVE_READ=$21
-      TIME_TS_RETRIEVE_OPEN=$22
-      TIME_TS_RETRIEVE_DONE=$23
-      TIME_MGM_RCOMMIT=$24
-      TIME_MGM_RETRIEVED=$25
+      TIME_FE_CLOSEW=$6
+      TIME_TS_ARCHIVE_POP=$7
+      TIME_TS_ARCHIVE_TASKS=$8
+      TIME_TS_ARCHIVE_OPEN=$9
+      TIME_TS_ARCHIVE_READ=$10
+      TIME_TS_ARCHIVE_DONE=$11
+      TIME_TS_ARCHIVE_REPORT=$12
+      TIME_MGM_ARCHIVED=$13
+      TIME_MGM_PREPARE=$14
+      TIME_FE_PREPARE=$15
+      TIME_TS_RETRIEVE_POP=$16
+      TIME_TS_RETRIEVE_TASK=$17
+      TIME_TS_RETRIEVE_TASKS=$18
+      TIME_TS_RETRIEVE_POSITION=$19
+      TIME_TS_RETRIEVE_READ=$20
+      TIME_TS_RETRIEVE_OPEN=$21
+      TIME_TS_RETRIEVE_DONE=$22
+      TIME_MGM_RCOMMIT=$23
+      TIME_MGM_RETRIEVED=$24
 
       printf "%d,%d,%f,%f,%f,%f,%f,%f,%f,%f,%f,%f,%f,%f,%f,%f,%f,%f,%f,%f,%f,%f\n",
         ARCHIVE_ID,FILE_ID,
         rel(TIME_MGM_CREATE,TIME_FE_CREATE),
-        rel(TIME_MGM_CREATE,TIME_MGM_ACOMMIT),
-        rel(TIME_MGM_ACOMMIT,TIME_MGM_CLOSEW),
-        rel(TIME_MGM_CLOSEW,TIME_FE_CLOSEW),
+        rel(TIME_FE_CREATE,TIME_MGM_ACOMMIT),
+        rel(TIME_MGM_ACOMMIT,TIME_FE_CLOSEW),
         rel(TIME_FE_CLOSEW,TIME_TS_ARCHIVE_POP),
         rel(TIME_TS_ARCHIVE_POP,TIME_TS_ARCHIVE_TASKS),
         rel(TIME_TS_ARCHIVE_TASKS,TIME_TS_ARCHIVE_OPEN),

continuousintegration/log_analysis/CI/preprocess.sh

@@ -39,15 +39,16 @@ process_mgm_log()
 
   awk -vDATE_OFFSET="$DATE_OFFSET" -vTEST_RUN=${TEST_RUN} 'BEGIN { COMMIT_EVENT="ACO" }
     function processLine(pattern, event, logline) {
-      gsub("time=.*" pattern, "", logline)
+      gsub("func=.*" pattern, "", logline)
       split(logline,logarray)
       DAYS=logarray[1]-DATE_OFFSET
       HOURS=substr(logarray[2],1,2)
       MINS=substr(logarray[2],4,2)
       SECS=substr(logarray[2],7,2)
+      MSECS=substr(logarray[3], index(logarray[3], "."), 7)
       timesecs=((DAYS*24 + HOURS)*60 + MINS)*60 + SECS
-      gsub("^.*" TEST_RUN "/", "", logarray[3])
-      print logarray[3],event,timesecs
+      gsub("^.*" TEST_RUN "/", "", logarray[4])
+      print logarray[4],event,timesecs MSECS
     }
 
     $0 !~ TEST_RUN { next }