Add writing-to-logfile calls before and after calling delegates

[Curious]

I have a method that uses a lot of delegates. Since there seems to be
a severe delay on UI (it takes a while before the tab displays the
file name), I'll need to add debugging info, specifically write to a
log file to record the time before and after each operation to
determine which part of the program causes the delay.

The relevant part of the code with debugging info added is below:

lWriter.Write("\"" + "before Add(mLoadingPage)" +
"\",");
lWriter.WriteLine();
lWriter.Write("\"" + DateTime.Now.ToString() + "\",");
lWriter.WriteLine();

this.tabControl.TabPages.Add(mLoadingPage);

//Load report files in the background
BackgroundWorker lLoadReportFilesWorker = new
BackgroundWorker();
lLoadReportFilesWorker.DoWork += new
DoWorkEventHandler(LoadReportFilesWorker_DoWork);

lWriter.Write("\"" + "before RunWorkerCompleted" +
"\",");
lWriter.WriteLine();
lWriter.Write("\"" + DateTime.Now.ToString() + "\",");
lWriter.WriteLine();

lLoadReportFilesWorker.RunWorkerCompleted += new
RunWorkerCompletedEventHandler(LoadReportFilesWorker_RunWorkerCompleted);

lWriter.Write("\"" + "before RunWorkerAsync" + "\",");
lWriter.WriteLine();
lWriter.Write("\"" + DateTime.Now.ToString() + "\",");
lWriter.WriteLine();


lLoadReportFilesWorker.RunWorkerAsync(lReport);

mStatusLoaded = true;
}
this.ResumeLayout(true);

lWriter.Write("\"" + "After ResumeLayout" + "\",");
lWriter.WriteLine();
lWriter.Write("\"" + DateTime.Now.ToString() + "\",");
lWriter.WriteLine();

I expected obvious time difference before and after the call to
"LoadReportFilesWorker_DoWork", because I stepped into this method
when debugging and paused for a while. However, the content of the log
shows that there's no time difference:

"before Add(mLoadingPage)",
"10/8/2007 9:37:37 AM",
"before RunWorkerCompleted",
"10/8/2007 9:37:37 AM",
"before RunWorkerAsync",
"10/8/2007 9:37:37 AM",
"After ResumeLayout",
"10/8/2007 9:37:37 AM",

Anyone can tell me why? Thanks

 

[Kevin Spencer]

Try logging milliseconds.

--
HTH,

Kevin Spencer
Microsoft MVP

DSI PrintManager, Miradyne Component Libraries:
http://www.miradyne.net

 

[Curious]

Kevin,

Thanks! I should have added logging info inside the event handler
methods instead of in the main method that defines the delegates.

It doesn't take time to delegate. However, it turns out that the delay
happens inside the event handler method such as DoWork.