github.com/swiftstack/proxyfs@v0.0.0-20201223034610-5434d919416e/jrpcfs/io_stats (about)

     1  #! /usr/bin/awk -f
     2  #
     3  # Command to parse periodic stats logs from proxyfsd.log
     4  # and count the average duration.
     5  #
     6  
     7  BEGIN {
     8     PROCINFO["sorted_in"] = "@ind_num_asc"
     9     defaultEventString = 36
    10     maxEventString = 36
    11  }
    12  {
    13      # Skip lines that we don't care about
    14      if ( $0 ~ /Periodic stats:/ )
    15      {
    16  	   # op is the 8th field. Strip the comma from the end.
    17  	   split($8, tempOp, ",")
    18  	   key = tempOp[1]
    19  
    20         #print "*** op is " key
    21  
    22  	   #print "Number of stats found: " $9 " " $10 " " $11 " " $12
    23  	   split($12, tempArray, ":")
    24  	   numberOfOps = tempArray[1]
    25  	   #print "Number of stats found: " numberOfOps
    26         numOps[key] += numberOfOps
    27  
    28         # Count fields, total duration is the ninth-last one
    29         #print "op is " key ", num ops is " numberOfOps ", duration is " $(NF-8)
    30         totalOpDurationsMs[key] += $(NF-8)
    31  
    32          # Parse out individual events, if present
    33          eventNumber = 1
    34  	    split($0, events, ";")
    35  		for (ev in events)
    36          {
    37  			#print "raw event " ev " is " events[ev]
    38  
    39  			# Look for "+" that each event has, but skip the "total duration" one, since it isn't an event
    40              if ((events[ev] ~ /\+/) && (events[ev] !~ /total duration/))
    41              {
    42  			    #print "event " eventNumber " is " events[ev]
    43  
    44  				# Event name is everything on left of "+", duration stuff on the right
    45  	            split(events[ev], eventDetail, "+")
    46  
    47  				eventName = eventDetail[1]
    48  
    49  				# Keep track of event name size, for print formatting later
    50  				if ( length(eventName) > maxEventString ) {
    51  					# +3 is for event number plus space
    52  				    maxEventString = length(eventName) + 3
    53  				}
    54  
    55  				# Event duration is the first field on rhs
    56  	            split(eventDetail[2], timingDetail, " ")
    57                  #print "  event duration: " timingDetail[1]
    58  
    59                  #print "storing OpEventMs["key"]["eventNumber " " eventName"] += " timingDetail[1]
    60                  OpEventMs[key][eventNumber " " eventName] += timingDetail[1]
    61  
    62  				# Number of events is also on the rhs
    63  				if (timingDetail[6] ~ /\[numEvents/)
    64  				{
    65  					# get the ] off the end of the number of events
    66  					split(timingDetail[7], numEventsDetail, "]")
    67  				    #print "number of events is ", numEventsDetail[1]
    68                      OpEventCount[key][eventNumber " " eventName] += numEventsDetail[1]
    69  				}
    70  
    71  	            eventNumber = eventNumber + 1
    72              }
    73          }
    74      }
    75  }
    76  END {
    77  	allOpsDurationMs = 0
    78  	allOpsCount = 0
    79      addlEventString = 0
    80  
    81  	if (maxEventString > defaultEventString)
    82  	{
    83          addlEventString = maxEventString - defaultEventString
    84  	}
    85  
    86      printf "\n"
    87      printf "                                           %" 24 + addlEventString "s\n",
    88  		   "  Total          Average"
    89      printf "Operation     Quantity                     %" 30 + addlEventString "s\n",
    90  		   "Duration (ms)    duration (ms)"
    91      printf "---------     --------                     %" 30 + addlEventString "s\n",
    92  		   "-------------    -------------"
    93      for (op in numOps)
    94      {
    95          if ( numOps[op] > 0 )
    96          {
    97              if (totalOpDurationsMs[op] > 0)
    98  			{
    99  				printf "%-12s   %5d                       %" 9 + addlEventString ".0f      %9.2f %8.2f %%\n",
   100  					op, numOps[op], totalOpDurationsMs[op], totalOpDurationsMs[op]/numOps[op],
   101  					totalOpDurationsMs[op]/totalOpDurationsMs[op] * 100
   102  
   103  				allOpsDurationMs += totalOpDurationsMs[op]
   104  				allOpsCount      += numOps[op]
   105  
   106  				if ( length(OpEventMs[op]) != 0 )
   107  				{
   108  			   		countedDurationMs = 0
   109  				  	for (event in OpEventMs[op])
   110  					{
   111  					   	#print "OpEventMs event is " event " = " OpEventMs[key][event]
   112  					  	printf "  (%-" maxEventString "s)   %9.0f      %9.2f %8.2f %%   (hits %5d/%5d)\n",
   113  					  		event, OpEventMs[op][event], OpEventMs[op][event]/numOps[op],
   114  					  		OpEventMs[op][event]/totalOpDurationsMs[op] * 100,
   115                              OpEventCount[op][event], numOps[op]
   116  						countedDurationMs += OpEventMs[op][event]
   117  				  	}
   118  
   119  					# Unaccounted doesn't make sense with these stats since we always have
   120  					# all the data. Comment this out.
   121  			  		#remainingDurationMs = totalOpDurationsMs[op] - countedDurationMs
   122  		   			#printf "  (%-36s)   %9.0f      %9.2f %8.2f %%\n",
   123  				 	#       "    unaccounted", remainingDurationMs, remainingDurationMs/numOps[op],
   124  					#       remainingDurationMs/totalOpDurationsMs[op] * 100
   125  			   	}
   126  			} else {
   127  				printf "%-12s   %5d                       %" 9 + addlEventString ".0f      %9.2f %8.2f %%\n",
   128  					op, numOps[op], totalOpDurationsMs[op], totalOpDurationsMs[op]/numOps[op], 100
   129  		    }
   130  
   131              print " "
   132          }
   133      }
   134  
   135      printf "%-12s   %5d                       %" 9 + addlEventString ".0f\n",
   136  		   "All ops", allOpsCount, allOpsDurationMs
   137      printf "\n"
   138  }