[Paraview] timer log, looks a bit off

[Berk Geveci]

Hi Bam,

I am vacation. I will respond when I get back. There does seem to be
something fishy indeed.

-berk

On Thu, Jul 9, 2009 at 8:09 PM, Bam Ting<bampingting at gmail.com> wrote:
> 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
>> >
>> >
>
>