[Paraview] timer log, looks a bit off
Bam Ting
bampingting at gmail.com
Thu Jul 9 20:09:21 EDT 2009
thank you for information! I attempt to check thing out myself, but not so
easy!
Something is not as you say it should be, but perhaps I make a wrong move
when I code my reader, so I really want to get this resolved, because as it
stands pipeline execute takes 80% while read if 1/2Gig only takes 20%. That
can't be correct!
I step in gdb and I see the stack has mixture of CompositeDataPipeline,
StreamingDemandDrivenPipeline, DemandDrivenPipeline, and Executive. In
addition to timing RequestData in the reader I time in ProcessRequest in
each of these classes to see where the hang up is. To my surprise I see that
many,many,many! things are going on after the reader finished RequestData.
Take a look at the io from the 2 process run that follws my text. I put
notes in with '===>' so you can see timing from RequestData easy. This io is
from a single pipeline update! For this one pipeline update I see timer log
report:
Execute vtkBAMReader id: 7750, 5.56547 seconds
lost + do not know what causes this! Plz HLP,
thx Bam.
n019:~/PV3-3.7-Debug/bin$mpiexec -np 2 ./pvserver --use-offscreen-rendering
--server-port=12345
Listen on port:
12345
Waiting for
client...
Client
connected.
DDP:ProcessRequest:RequestDataObject:0:0DDP:ProcessRequest:RequestDataObject:
1:0.01
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0.01
CDP:ProcessRequest:RequestInformation:1:0.01
CDP:ProcessRequest:RequestDataObject:0:CDP:ProcessRequest:RequestDataObject:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:CDP:ProcessRequest:RequestInformation:0:0
1:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:CDP:ProcessRequest:RequestInformation:0:0
1:0
CDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
CDP:ProcessRequest:RequestInformation:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
=================================================>>Read happens from here
RequestData n019 0
135796744
RequestData n019 0 0 513 0 513 0
256
RequestData n012 1
135796744
RequestData n012 1 0 513 0 513 256
513
RequestData n019 0 RequestData n012 1
1.01
1
DDP:ProcessRequest:RequestData:0:1.01
SDDP:ProcessRequest:RequestData+Crop:0:1.01
DDP:ProcessRequest:RequestData:1:1
SDDP:ProcessRequest:RequestData+Crop:1:1
================================================>> to here! takes 1.01 sec.
What follow take ~ 5
sec
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1CDP:ProcessRequest:RequestInformation:0:0
:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
CDP:ProcessRequest:RequestInformation:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1DDP:ProcessRequest:RequestDataObject:0:0
:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestDataObject:0:CDP:ProcessRequest:RequestDataObject:1:0
0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestDataObject:0CDP:ProcessRequest:RequestDataObject:1:0
:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
:0
CDP:ProcessRequest:RequestDataObject:0:CDP:ProcessRequest:RequestDataObject:1:0
0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:CDP:ProcessRequest:RequestDataObject:0:0
0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestDataObject:0:CDP:ProcessRequest:RequestDataObject:1:0
0
CDP:ProcessRequest:RequestInformation:0:CDP:ProcessRequest:RequestInformation:1:0
0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestDataObject:0CDP:ProcessRequest:RequestDataObject:1:0
:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
:0
CDP:ProcessRequest:RequestDataObject:0:CDP:ProcessRequest:RequestDataObject:1:0
0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestDataObject:0:CDP:ProcessRequest:RequestDataObject:1:0
0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestDataObject:0:CDP:ProcessRequest:RequestDataObject:1:0
0.01
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0.01
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0.01
CDP:ProcessRequest:RequestDataObject:1:0.01
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestDataObject:0:CDP:ProcessRequest:RequestDataObject:1:0
0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestDataObject:0CDP:ProcessRequest:RequestDataObject:1:0
:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0.01
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
DDP:ProcessRequest:RequestData:1:0
SDDP:ProcessRequest:RequestData+Crop:1:0
CDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestData:1:0
SDDP:ProcessRequest:RequestData+Crop:1:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestData:1:0
SDDP:ProcessRequest:RequestData+Crop:1:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:CDP:ProcessRequest:RequestInformation:1:0
0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
DDP:ProcessRequest:RequestData:1:0
SDDP:ProcessRequest:RequestData+Crop:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:1:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
DDP:ProcessRequest:RequestData:1:0
SDDP:ProcessRequest:RequestData+Crop:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
DDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestData:1:0.01
DDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
SDDP:ProcessRequest:RequestData+Crop:1:0.01
DDP:ProcessRequest:RequestData:1:0.01
SDDP:ProcessRequest:RequestData+Crop:1:0.01
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestData:1:0.01
SDDP:ProcessRequest:RequestData+Crop:1:0.01
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestData:0:0.01
SDDP:ProcessRequest:RequestData+Crop:0:0.01
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestDataObject:0:0
DDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
DDP:ProcessRequest:RequestData:0:0.01
SDDP:ProcessRequest:RequestData+Crop:0:0.01
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestDataObject:0:CDP:ProcessRequest:RequestDataObject:1:0
0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:0
SDDP:ProcessRequest:RequestUpdateExtent:0:0
0
SDDP:ProcessRequest:RequestUpdateExtent:1:0
DDP:ProcessRequest:RequestData:1:0
SDDP:ProcessRequest:RequestData+Crop:1:0
DDP:ProcessRequest:RequestData:0:0
SDDP:ProcessRequest:RequestData+Crop:0:0
CDP:ProcessRequest:RequestDataObject:0:0
CDP:ProcessRequest:RequestDataObject:1:0
CDP:ProcessRequest:RequestInformation:0:0
DDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:0:CDP:ProcessRequest:RequestInformation:1:0
DDP:ProcessRequest:RequestInformation:1:0
CDP:ProcessRequest:RequestInformation:1:00
CDP:ProcessRequest:RequestInformation:0:0
CDP:ProcessRequest:RequestInformation:1:0
On Thu, Jul 9, 2009 at 6:41 AM, Berk Geveci <berk.geveci at kitware.com> wrote:
> If you are look at a line like:
>
> Execute vtkSphereSource id: 115, 0.256536 seconds
>
> where vtkSphereSource should be replaced with your reader, it should
> be only the timing for your reader from right before its execution to
> right after. If you are looking at the render time, it would include
> other things. In the rest of the message, I am assuming that you are
> looking at a line like the one above. Even if not, some of my answers
> should shed some light on how timing works.
In fact
>
>
> During the RequestData pass, the executive does the following:
>
> - vtkDemandDrivePipeline::ExecuteDataStart() -> calls
> this->Algorithm->UpdateProgress(0.0) at the end
> - calls your algorithm
> - vtkDemandDrivePipeline::ExecuteDataEnd() -> calls
> this->Algorithm->UpdateProgress(1.0) at the beginning
>
> The timer log reports the time that passed between progress 0 and 1.
> There seems to be a big discrepancy between this number and what your
> timing show. So I'd guess that there is a bug somewhere. If you are
> calling UpdateProgress(), can you verify that it is doing the right
> thing? Also, you can insert your own timing code in
> vtkDemandDrivenPipeline to look for a bug in ParaView.
>
> > The more important question: What is going on behind the scenes in those
> 5
> > seconds after my reader executes?
>
> I am going to say nothing - barring any bugs.
>
> > Can we safely say it's client server communication?
>
> Nope. The timing should not include any client-server communication.
>
> > ParaView wont try to load ballance behind my back will it?
>
> It depends. If this reader produces polydata or unstructured grid, are
> you setting MAXIMUM_NUMBER_OF_PIECES to -1 in RequestInformation? If
> this reader produces one of the structured datasets, are you producing
> exactly the UPDATE_EXTENT? Either way, the timing should not include
> any load balancing ParaView does. That should be reported separately.
>
> On Tue, Jul 7, 2009 at 8:49 PM, Bam Ting<bampingting at gmail.com> wrote:
> > testing my reader plugin, I thought timer log would be a good way to go,
> > however not so sure what it's timing. running in client server mode, 2 ,
> 4
> > and 8 processes so far.
> >
> > I put some time computation in my request data method that show the read
> > takes less than 1 second on all processes and decreases as process are
> > added, however timer log reports nearly 6 seconds on all runs.
> >
> > The more important question: What is going on behind the scenes in those
> 5
> > seconds after my reader executes?
> >
> > Can we safely say it's client server communication?
> >
> > ParaView wont try to load ballance behind my back will it?
> >
> >
> > _______________________________________________
> > Powered by www.kitware.com
> >
> > Visit other Kitware open-source projects at
> > http://www.kitware.com/opensource/opensource.html
> >
> > Please keep messages on-topic and check the ParaView Wiki at:
> > http://paraview.org/Wiki/ParaView
> >
> > Follow this link to subscribe/unsubscribe:
> > http://www.paraview.org/mailman/listinfo/paraview
> >
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.paraview.org/pipermail/paraview/attachments/20090709/85467b2a/attachment-0001.htm>
More information about the ParaView
mailing list