Mysterious perf problem...could it be Date.Now? (long post)

[David]

We've developed a seismic-data processing app in VB.NET 1.1 which runs on XP
Pro using SQL2K. Like all seismic data apps, it deals with HUGE amounts of
binary data (we use NTFS sparse "flat files") ... a typical user will have a
20 Terabyte raid array.

During a particular operation that reads, formats and exports these files,
we've noticed that sometimes it runs rather slowly... like it might take 12
hours to finish exporting the same amount of data that on another (identical)
export would take only 2 hours or so.

In troubleshooting, we noticed something peculiar: The app writes messages
to a (text) log while it is exporting the data, and when the "slowness"
problem is occuring, the timestamps in those messages are precisely 1 second
apart. Here's a sequence of messages showing two back-to-back files being
exported (of hundreds of thousands in a typical export operation):

09/19/2006 07:44:08.860 PM [InfoMsg]: Reading file 00001102.0.0249.0.3.uad
…
09/19/2006 07:44:09.860 PM [InfoMsg]: Wrote 2050 samples read from file
00001102.0.0249.0.3.uad …
09/19/2006 07:44:09.860 PM [InfoMsg]: Reading file 00001263.0.0249.0.1.uad …
09/19/2006 07:44:10.860 PM [InfoMsg]: Wrote 2050 samples read from file
00001263.0.0249.0.1.uad …

Notice that there is exactly 1 second between the “Reading file� and “Wrote
samples� messages. This same pattern (of messages separated by exactly 1
second) can continue for several hours.

But when the “slowness� problem isn’t occuring, these two messages are
separated by just a few milliseconds, and more significantly, the interval
between them tends to vary a bit, as one would expect.

So, what kind of mechanisms in XP or .NET 1.1 could explain what would
“block� an app for precisely one second? I don’t think that a “resource�
constraint (CPU, memory, network, disk) could explain this precise one second
interval.

My suspicion is that the app is being blocked at the moment I invoke
Date.Now to log the message:

_log.WriteLine(Date.Now.ToString("MM/dd/yyyy hh:mm:ss.fff tt") & " [" &
messageType.ToString & "]: " & message)

…at least that would explain all the symptoms we’re seeing.

But I don’t know how to address it. If I remove the call to Date.Now, I’ll
lose the most critical bit of information in the message log!

Any advice would be greatly appreciated!

Stuck in Houston…

[Dave Sexton]

Hi David,

(By Date.Now, do you mean DateTime.Now? Maybe that's just a VB thing...)

I don't know of any reason why DateTime.Now would block, but just to be sure you could try replacing DateTime.Now (or Date.Now :)
with Environment.TickCount / 1000 so you'll be able to see the number of seconds elapsed between those tasks in the log file.

HTH

--
Dave Sexton

"David" <Da***@discussions.microsoft.comwrote in message news:E6**********************************@microsof t.com...

We've developed a seismic-data processing app in VB.NET 1.1 which runs on XP
Pro using SQL2K. Like all seismic data apps, it deals with HUGE amounts of
binary data (we use NTFS sparse "flat files") ... a typical user will have a
20 Terabyte raid array.

During a particular operation that reads, formats and exports these files,
we've noticed that sometimes it runs rather slowly... like it might take 12
hours to finish exporting the same amount of data that on another (identical)
export would take only 2 hours or so.

In troubleshooting, we noticed something peculiar: The app writes messages
to a (text) log while it is exporting the data, and when the "slowness"
problem is occuring, the timestamps in those messages are precisely 1 second
apart. Here's a sequence of messages showing two back-to-back files being
exported (of hundreds of thousands in a typical export operation):

09/19/2006 07:44:08.860 PM [InfoMsg]: Reading file 00001102.0.0249.0.3.uad
.
09/19/2006 07:44:09.860 PM [InfoMsg]: Wrote 2050 samples read from file
00001102.0.0249.0.3.uad .
09/19/2006 07:44:09.860 PM [InfoMsg]: Reading file 00001263.0.0249.0.1.uad .
09/19/2006 07:44:10.860 PM [InfoMsg]: Wrote 2050 samples read from file
00001263.0.0249.0.1.uad .

Notice that there is exactly 1 second between the "Reading file" and "Wrote
samples" messages. This same pattern (of messages separated by exactly 1
second) can continue for several hours.

But when the "slowness" problem isn't occuring, these two messages are
separated by just a few milliseconds, and more significantly, the interval
between them tends to vary a bit, as one would expect.

So, what kind of mechanisms in XP or .NET 1.1 could explain what would
"block" an app for precisely one second? I don't think that a "resource"
constraint (CPU, memory, network, disk) could explain this precise one second
interval.

My suspicion is that the app is being blocked at the moment I invoke
Date.Now to log the message:

_log.WriteLine(Date.Now.ToString("MM/dd/yyyy hh:mm:ss.fff tt") & " [" &
messageType.ToString & "]: " & message)

.at least that would explain all the symptoms we're seeing.

But I don't know how to address it. If I remove the call to Date.Now, I'll
lose the most critical bit of information in the message log!

Any advice would be greatly appreciated!

Stuck in Houston.

[Dr. Jochen Manns]

Could it be the Garbage Collector which starts a separate thread when
necessary and needs some to to process? I would be a good idea to use
perfmon an the .NET / GC related performance counters for more detailed
inspection.

Eventually running in a Virtual Machine (VMWare) can reduce virtual CPU
power in some scenario (although we only saw this when the running (guest)
operation system is Win2k).

"David" <Da***@discussions.microsoft.comwrote in message
news:E6**********************************@microsof t.com...

We've developed a seismic-data processing app in VB.NET 1.1 which runs on
XP
Pro using SQL2K. Like all seismic data apps, it deals with HUGE amounts of
binary data (we use NTFS sparse "flat files") ... a typical user will
have a
20 Terabyte raid array.

During a particular operation that reads, formats and exports these files,
we've noticed that sometimes it runs rather slowly... like it might take
12
hours to finish exporting the same amount of data that on another
(identical)
export would take only 2 hours or so.

In troubleshooting, we noticed something peculiar: The app writes
messages
to a (text) log while it is exporting the data, and when the "slowness"
problem is occuring, the timestamps in those messages are precisely 1
second
apart. Here's a sequence of messages showing two back-to-back files being
exported (of hundreds of thousands in a typical export operation):

09/19/2006 07:44:08.860 PM [InfoMsg]: Reading file 00001102.0.0249.0.3.uad
.
09/19/2006 07:44:09.860 PM [InfoMsg]: Wrote 2050 samples read from file
00001102.0.0249.0.3.uad .
09/19/2006 07:44:09.860 PM [InfoMsg]: Reading file
00001263.0.0249.0.1.uad .
09/19/2006 07:44:10.860 PM [InfoMsg]: Wrote 2050 samples read from file
00001263.0.0249.0.1.uad .

Notice that there is exactly 1 second between the "Reading file" and
"Wrote
samples" messages. This same pattern (of messages separated by exactly 1
second) can continue for several hours.

But when the "slowness" problem isn't occuring, these two messages are
separated by just a few milliseconds, and more significantly, the interval
between them tends to vary a bit, as one would expect.

So, what kind of mechanisms in XP or .NET 1.1 could explain what would
"block" an app for precisely one second? I don't think that a "resource"
constraint (CPU, memory, network, disk) could explain this precise one
second
interval.

My suspicion is that the app is being blocked at the moment I invoke
Date.Now to log the message:

_log.WriteLine(Date.Now.ToString("MM/dd/yyyy hh:mm:ss.fff tt") & " [" &
messageType.ToString & "]: " & message)

.at least that would explain all the symptoms we're seeing.

But I don't know how to address it. If I remove the call to Date.Now, I'll
lose the most critical bit of information in the message log!

Any advice would be greatly appreciated!

Stuck in Houston.