Determining the run time of a process.

I have had several cases through my professional career where I have developed background processes that handle recurring tasks, such as renewing subscriptions or retrieving history for a batch of customers. These are normally implemented as Windows Services, which means I generally log the status of the process, as well as any summary data for its last execution, to the Application Event Log.

One piece of data I like to include in my summary log entry is how long a processing cycle took to execute. This data point is helpful for routine benchmarking, as well as determining if a process has gone rogue and is taking unusually long to complete (possibly due to a remote service latency or something like that.)

Using the provide Date related objects in .NET makes it easy to determine and report this execution time.

First, define some variables for the summary report:

Dim startTime As DateTime = DateTime.Now()
Dim recordsToProcess As Integer = 0
Dim recordsProcessed As Integer = 0
Dim recordsErrored As Integer = 0

I typically am pulling records to process from a database query, and so setting up the processing loop is pretty straight forward.

recordsToProcess = dataSetWithRecords.Tables(0).Rows.Count

For Each drCurrentRecord As DataRow In dataSetWithRecords.Tables(0).Rows

'do processing here
Try
    'execute task
     .
     .
     .
    'update success counter
    recordsProcessed += 1
Catch ex as Exception
    'handle error state
    'update error counter
    recordsErrored += 1
End Try
Next

Now I can capture and calculate the processing time. I use the DateDiff() method to determine the number of seconds between the start and end timestamps. Then, using the TimeSpan object I have an easy to use representation of the time elapsed that I can put in my summary message.

Dim endTime As DateTime = DateTime.Now
Dim timeElapsedSeconds As Double = DateDiff(DateInterval.Second, startTime, endTime)
Dim timeElapsedSpan As TimeSpan = New TimeSpan(0, 0, timeElapsedseconds)

Dim sbSummary As New System.Text.StringBuilder
sbSummary.AppendLine("Agent Results:")
sbSummary.AppendFormat("Total records to process:{0}", recordsToProcess.ToString)
sbSummary.AppendLine()
sbSummary.AppendFormat("Records processed Successfully: {0}",recordsProcessed.ToString)
sbSummary.AppendLine()
sbSummary.AppendFormat("Records with errors:  {0}", recordsErrored.ToString)
sbSummary.AppendLine()
sbSummary.AppendFormat("Processing Time: {0} Hours, {1} Minutes, {2} Seconds", timeElapsedSpan.Hours, timeElapsedSpan.Minutes, timeElapsedSpan.Seconds)
sbSummary.AppendLine()

LogMessage(sbSummary.ToString)

This approach is reliable, accurate, and keeps me from having to manually calculate the elapsed time.