C# Code to parse a text file and calculate time difference

true image

Hi, I'd like to parse a log file and grab the timestamps at the start of specific lines in pairs and then find the time difference to see how long it took.

Here's a dummy example of the file contents:

2013-05-28 16:39:54,185 [http-8080-8 UserName] DEBUG DynamicDialogService.java:395 - DynamicDialogService.getDialogDescriptors()

2013-05-28 16:39:54,935 [http-8080-8 UserName] DEBUG ControlDescriptor.java:213 - Populating value of control Control1

2013-05-28 16:39:54,935 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'Control1', value: 'test'

2013-05-28 16:39:55,060 [http-8080-8 UserName] DEBUG ControlDescriptor.java:213 - Populating value of control Control2

2013-05-28 16:39:55,060 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'Control2', value: '2'

2013-05-28 16:39:55,076 [http-8080-8 UserName DEBUG ControlDescriptor.java:213 - Populating value of control Control3

//many lines of logging

2013-05-28 16:39:55,154 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'Control3 value: 'null'

2013-05-28 16:39:55,576 [http-8080-8 UserName] DEBUG ControlDescriptor.java:213 - Populating value of control Control4

//many lines of logging

2013-05-28 16:39:55,857 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'Control4', value: 'null'

2013-05-28 16:39:59,482 [http-8080-8 UserName] DEBUG DynamicDialogService.java:417 - Got descriptors. Building result object.

There are a few main components to the file:

"DynamicDialogService.getDialogDescriptors" designates the start of one action. There may be several of these in each file. The subsequent "controls" belong to this action.

"ControlDescriptor.java:213" designates the start of a "control" with a name
"ControlDescriptor.java:266" designates the end of a "control" with a matching name

Subtracting the start timestamp from the end timestamp gives the total time elapsed for that control

"Got descriptors. Building result object." designates the end of an action. again, getting this timestamp for subtraction along with the start of the action gives a total time elapsed for that action.

Any help / code / suggestions on how to tackle this would be great.

4 Replies

Know the answer? Post it — somebody with the same question will find it here.

Vulpes13y ago
Accepted answer
I've just had a quick look at the additional scenarios and I think we'll need to introduce regular expressions to sort out the 'end' of the controls as we can't rely on the control name being in a fixed position in the items array.

Try the following - changes highlighted. If it's not quite right, I'll try and fix it tomorrow:

using System;
using System.IO;
using System.Text.RegularExpressions;

class Prgram
{
static void Main()
{
string format = "yyyy-MM-dd HH:mm:ss,fff";
char[] spaceArray = new char[]{' '};
string regExp = @"Completed population of control '?(\w+)\W";

using (StreamReader sr = new StreamReader("trueimage.log"))
{
string line;
int action = 0;
string controlBegin = null;
string controlEnd = null;
string dts = null;
DateTime timeBegin = DateTime.MinValue;
DateTime timeEnd = DateTime.MinValue;
int ms = 0;

while((line = sr.ReadLine()) != null)
{
if (line.Trim().Length == 0) continue; //ignore empty lines
if (line.StartsWith("//")) continue; // ignore comments
if (line.EndsWith("DynamicDialogService.getDialogDescriptors()"))
{
action++;
Console.WriteLine("Action {0} starting\n", action);
}
else if (line.EndsWith("Building result object."))
{
Console.WriteLine("\nAction {0} ending\n", action);
}
else if(line.Contains("ControlDescriptor.java:213"))
{
string[] items = line.Split(spaceArray,

StringSplitOptions.RemoveEmptyEntries);
dts = String.Format("{0} {1}", items[0], items[1]);
controlBegin = items[items.Length - 1];
timeBegin = DateTime.ParseExact(dts, format, null);
}
else if(line.Contains("ControlDescriptor.java:266"))
{
string[] items = line.Split(spaceArray,

StringSplitOptions.RemoveEmptyEntries);
controlEnd = Regex.Match(line, regExp).Groups[1].Value;

if (controlBegin != controlEnd)
{
Console.WriteLine("Matching pair not found for {0}", controlBegin);
}
else
{
dts = String.Format("{0} {1}", items[0], items[1]);
timeEnd = DateTime.ParseExact(dts, format, null);
ms = (int)(timeEnd - timeBegin).TotalMilliseconds;
Console.WriteLine(" {0} took {1} milliseconds", controlBegin, ms);
}
}
}
}
}
}
true image13y ago
Vulpes, this works great after some modifications to make it work for a Windows Form application. Thanks!

One issue is it doesn't always find an "end" for the control with this code:

controlEnd = items[items.Length - 3].Replace(",", "").Replace("'", "");

It certainly works for the examples I've provided. Here are a bunch more scenarios.

Line 918: 2013-05-22 18:22:17,170 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidApplicationId', value: '0b01221a80002d90'
Line 920: 2013-05-22 18:22:17,170 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtDocumentNumber', value: 'null'
Line 922: 2013-05-22 18:22:17,170 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtDocumentNumberSyntax', value: '----'
Line 924: 2013-05-22 18:22:17,185 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'temp_hidTemplateTitle', value: 'null'
Line 926: 2013-05-22 18:22:17,185 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidPlantIndex', value: '0'
Line 928: 2013-05-22 18:22:17,185 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidCategoryIndex', value: '1'
Line 930: 2013-05-22 18:22:17,185 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidDiscplineIndex', value: '2'
Line 932: 2013-05-22 18:22:17,185 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidSequenceIndex', value: '3'
Line 934: 2013-05-22 18:22:17,201 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidSequenceLength', value: '4'
Line 936: 2013-05-22 18:22:17,201 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidSheetIndex', value: '4'
Line 938: 2013-05-22 18:22:17,201 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidSheetLength', value: '2'
Line 998: 2013-05-22 18:22:17,216 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidDocumentsWithSameName', value: 'null'
Line 1479: 2013-05-22 18:22:17,341 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboPlantNumber', value: 'null'
Line 1515: 2013-05-22 18:22:17,388 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboCatLevel1', value: 'GENERAL'
Line 1959: 2013-05-22 18:22:17,451 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboCatLevel2', value: 'null'
Line 2028: 2013-05-22 18:22:17,482 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidMasterGroupForDisciplines', value: 'null'
Line 2458: 2013-05-22 18:22:19,013 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboDiscipline', value: 'null'
Line 2523: 2013-05-22 18:22:19,044 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtSequenceNumber', value: 'null'
Line 2588: 2013-05-22 18:22:19,076 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtSheetNumber', value: 'null'
Line 2693: 2013-05-22 18:22:19,107 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidValidationText', value: 'FAIL:Document Number has not been entered'
Line 2755: 2013-05-22 18:22:19,154 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtTitle', value: 'null'
Line 2757: 2013-05-22 18:22:19,154 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtExternalNumber', value: 'null'
Line 2760: 2013-05-22 18:22:19,154 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtRevisionNumber', value: ''
Line 3008: 2013-05-22 18:22:19,279 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboNewState', value: 'Received'
Line 3075: 2013-05-22 18:22:19,310 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidMasterGroupForProjects', value: 'master_group'
Line 33755: 2013-05-22 18:26:29,147 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboProjectNumber', value: 'null'
Line 33817: 2013-05-22 18:26:29,178 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboDepartment', value: 'null'
Line 33819: 2013-05-22 18:26:29,178 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtTrainNumber', value: 'null'
Line 33878: 2013-05-22 18:26:29,194 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtValidationError', value: 'FAIL:Document Number has not been entered'
Line 33880: 2013-05-22 18:26:29,194 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'btnValidate', value: 'null'
Line 33882: 2013-05-22 18:26:29,194 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'hidHasBeenValidated', value: 'false'
Line 33917: 2013-05-22 18:26:29,209 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboCatLevel3', value: 'null'
Line 33990: 2013-05-22 18:26:29,225 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtCategoryFixer', value: 'GENERAL'
Line 34070: 2013-05-22 18:26:29,256 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboClasslevel1', value: 'null'
Line 34150: 2013-05-22 18:26:29,272 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboClasslevel2', value: 'null'
Line 34230: 2013-05-22 18:26:29,288 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboClasslevel3', value: 'null'
Line 34295: 2013-05-22 18:26:29,334 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'datValidUntil', value: '2014/05/23 00:26:29'
Line 35191: 2013-05-22 18:26:29,537 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtDescription', value: ''
Line 35312: 2013-05-22 18:26:29,584 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboPhysicalLocation', value: 'null'
Line 36265: 2013-05-22 18:26:29,834 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboBuildingNumber', value: 'null'
Line 38721: 2013-05-22 18:26:30,209 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboVendorName', value: 'null'
Line 38724: 2013-05-22 18:26:30,209 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtVendorDocumentNumber', value: ''
Line 38727: 2013-05-22 18:26:30,225 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtVendorRevisionNumber', value: ''
Line 38730: 2013-05-22 18:26:30,225 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtSubject', value: ''
Line 47408: 2013-05-22 18:26:31,584 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'grdContractNumbers', value: 'null'
Line 48832: 2013-05-22 18:26:31,959 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboKeyCode', value: 'null'
Line 48913: 2013-05-22 18:26:32,069 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'grdEquipmentCodes', value: 'null'
Line 48979: 2013-05-22 18:26:32,100 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'grdEquipmentCodeGatherer', value: 'null'
Line 48981: 2013-05-22 18:26:32,100 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'lblMissing', value: 'null'
Line 48983: 2013-05-22 18:26:32,100 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'lblMissing2', value: 'null'
Line 49094: 2013-05-22 18:26:32,131 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'grdEquipmentCodeMissing', value: 'null'
Line 49096: 2013-05-22 18:26:32,131 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'chkAllowMissingRemoval', value: 'null'
Line 49099: 2013-05-22 18:26:32,131 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtCommodityCode', value: 'null'
Line 49102: 2013-05-22 18:26:32,131 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'txtSystemNumber', value: ''
Line 66261: 2013-05-22 18:26:34,678 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'grdAuthors', value: 'null'
Line 66332: 2013-05-22 18:26:34,694 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboPaperSize', value: 'null'
Line 66399: 2013-05-22 18:26:34,725 [http-8080-8 UserName] DEBUG ControlDescriptor.java:266 - Completed population of control 'cboOrientation', value: '1'
Vulpes13y ago
Try this:

using System;
using System.IO;

class Prgram
{
static void Main()
{
string format = "yyyy-MM-dd HH:mm:ss,fff";
char[] spaceArray = new char[]{' '};

using (StreamReader sr = new StreamReader("trueimage.log"))
{
string line;
int action = 0;
string controlBegin = null;
string controlEnd = null;
string dts = null;
DateTime timeBegin = DateTime.MinValue;
DateTime timeEnd = DateTime.MinValue;
int ms = 0;

while((line = sr.ReadLine()) != null)
{
if (line.Trim().Length == 0) continue; //ignore empty lines
if (line.StartsWith("//")) continue; // ignore comments
if (line.EndsWith("DynamicDialogService.getDialogDescriptors()"))
{
action++;
Console.WriteLine("Action {0} starting\n", action);
}
else if (line.EndsWith("Building result object."))
{
Console.WriteLine("\nAction {0} ending\n", action);
}
else if(line.Contains("ControlDescriptor.java:213"))
{
string[] items = line.Split(spaceArray, StringSplitOptions.RemoveEmptyEntries);
dts = String.Format("{0} {1}", items[0], items[1]);
controlBegin = items[items.Length - 1];
timeBegin = DateTime.ParseExact(dts, format, null);
}
else if(line.Contains("ControlDescriptor.java:266"))
{
string[] items = line.Split(spaceArray, StringSplitOptions.RemoveEmptyEntries);
controlEnd = items[items.Length - 3].Replace(",", "").Replace("'", "");

if (controlBegin != controlEnd)
{
Console.WriteLine("Matching pair not found for {0}", controlBegin);
}
else
{
dts = String.Format("{0} {1}", items[0], items[1]);
timeEnd = DateTime.ParseExact(dts, format, null);
ms = (int)(timeEnd - timeBegin).TotalMilliseconds;
Console.WriteLine(" {0} took {1} milliseconds", controlBegin, ms);
}
}
}
}
}
}
Sunny Sharma13y ago
Hi,

Is there another keywords also like you mentioned - "DynamicDialogService.getDialogDescriptors" and "Got Descriptors"? or they're only the two for which you want them to tracked?