Diagnosing a pregnant pause.

[BrowserUk]

When I run an evolution of this script with a particular set of arguments: Ibufd.pl -IBUF=20971520 -NBUF=6000 1GB.csv, about 18 seconds into a 2 minute run, the cpu and IO activity suddenly drop to 0 and stay there for 3 seconds. Memory requirements are exactly stable at that point in time and the overall memory requirements are well within the bounds of my free physical storage.

I've posted a screen grab graphing the cpu/memory/IO history of the entire process run here. The vertical divisions represent 3 seconds. This is entirely consistent regardless of what else is running or how many times I re-run the test.

I'm trying to track down the cause of the pause. I've tried several methods of trying to instrument the process, but all of them completely change the performance characteristics of the process rendering all the information produced meaningless. My purpose in posting is to try and get answers to the following questions:

1. Is this down to my system?

   If anyone running Win64/AS1007 can reproduce the graph it might be helpful.

   If anyone with a non-windows system has the tools to produce a similar graph (or at least data points) on their system, that might be even more useful.

2. How can I work out what is going on inside the script during those 3 seconds?

   At it simplest, a time-point/line-number trace might shed some light, but how can I produce it without changing the performance characteristics?

3. Anyone have any thoughts, evidence or just wild speculations (preferably not alien-based) as to what might be the cause?

   Speculations accompanied by mechanisms of how to verify would be most useful.

To aid anyone thinking of trying to reproduce the problem, this script (with default options) will create a 1GB CSV file consistent with the input expectation of the script:

<Reveal this spoiler or all spoilers in this node or all in this thread>

And this is the evolved script, the required command line is shown at the bottom:

<Reveal this spoiler>

A hearty thank-you to anyone taking the time to help me with this.

[ikegami]

http://imagebin.org/170962

ActivePerl v5.14.0 build 1400 built for MSWin32-x86-multi-thread

Win7 Pro 64 bit (32 bit Perl, though)

[Anonymous Monk]

Okay ... it's waiting on a mutex of some kind, and it has a three-second timeout. That much we know. But, what happens "consistently, 18 seconds into the run," in your application logic? What does it do ask-for differently at that one point in time, and only at that one point in time?

[BrowserUk]

If you'd looked at the code, you'd see that it spends its entire time in a loop doing the same things -- reading from an input file and writing to many output files -- over and over.

The pause appears to occur when the cumulative affect of many writes to many output files exhausts the file cache buffers and it needs to flush them to disk en-masse before it can continue.

The intriguing thing was why this pregnant pause would only occur once, rather early in the run. The answer to that appears to be that the OS defers allocating disk extants to output files until it needs to flush the first write from the cache.