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<bampingt...@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.gev...@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<bampingt...@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 >> > >> > > > _______________________________________________ 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