Timer log is incorrect for CTH
I am pretty sure the timer log is missing lots of stuff in the general case, but I am going to write up this bug for CTH. With CTH, it needs to capture more of what is going on.
Test case:
- master, about November 30, 2017. Linux. local server.
- ParaView: v5.4.1-870-gf3267876
- Superbuild: v5.4.1-119-ga0ca86c
- Load Dave's small dataset. All vars on. Apply. First, we are going to test ExtractCTHParts.
- ExtractCTHParts. Material Volume Fraction - 1. Apply.
- Go to timestep 10.
- Tools/ Timer Log/ Clear.
- Step forward one timestep. With a clock, count how many seconds this takes.
- Tools/ Timer Log/ Refresh. Show All.
I counted about 6 seconds. Here is what I see:
'''
RenderView::Update, 3.24526 seconds
vtkPVView::Update, 3.24477 seconds
'''
Execute vtkSpyPlotReader id: 7503, 1.11723 seconds
Execute vtkGeometryRepresentationWithFaces id: 8006, 0.001181 seconds
Execute vtkPVExtractSelection id: 7505, 3e-05 seconds
Execute vtkGeometryRepresentationWithFaces id: 8208, 0.000816 seconds
vtkPVGeometryFilter::RequestData, 4.8e-05 seconds
vtkPVGeometryFilter::RequestCompositeData, 3.6e-05 seconds
vtkPVGeometryFilter::CheckAttributes, 6e-06 seconds
vtkPVGeometryFilter::ExecuteCompositeDataSet, 1.7e-05 seconds
vtkPVGeometryFilter::GarbageCollect, 2e-06 seconds
Execute vtkPVExtractSelection id: 7506, 2.7e-05 seconds
vtkPVGeometryFilter::RequestData, 3.4e-05 seconds
vtkPVGeometryFilter::RequestCompositeData, 2.7e-05 seconds
vtkPVGeometryFilter::CheckAttributes, 6e-06 seconds
vtkPVGeometryFilter::ExecuteCompositeDataSet, 1.4e-05 seconds
vtkPVGeometryFilter::GarbageCollect, 1e-06 seconds
Execute vtkExtractCTHPart id: 8905, 1.69277 seconds
Execute vtkGeometryRepresentationWithFaces id: 9097, 0.024381 seconds
vtkPVGeometryFilter::RequestData, 0.011782 seconds
vtkPVGeometryFilter::RequestCompositeData, 0.011772 seconds
vtkPVGeometryFilter::CheckAttributes, 1.1e-05 seconds
vtkPVGeometryFilter::ExecuteCompositeDataSet, 0.011736 seconds
vtkPVGeometryFilter::GarbageCollect, 2e-06 seconds
Execute vtkPVExtractSelection id: 8906, 2.5e-05 seconds
vtkPVGeometryFilter::RequestData, 5.5e-05 seconds
vtkPVGeometryFilter::RequestCompositeData, 4.1e-05 seconds
vtkPVGeometryFilter::CheckAttributes, 5e-06 seconds
vtkPVGeometryFilter::ExecuteCompositeDataSet, 2.5e-05 seconds
vtkPVGeometryFilter::GarbageCollect, 1e-06 seconds
spcthreader::GatherInformation, 2.82023 seconds
spcthreader::GatherInformation, 0.000519 seconds
spcthreader::GatherInformation, 0.00039 seconds
vtkSMRepresentationProxy::GetRepresentedDataInformation, 9.6e-05 seconds
vtkSMRepresentationProxy::GetRepresentedDataInformation, 2.9e-05 seconds
CTHPart::GatherInformation, 0.024414 seconds
vtkSMRepresentationProxy::GetRepresentedDataInformation, 0.008452 seconds
vtkSMDataDeliveryManager: Deliver Geometry, 0.003653 seconds
FullRes Data Migration, 0.003451 seconds
Still Render, 0.047382 seconds
OpenGL Dev Render, 0.006973 seconds
OpenGL Dev Render, 0.00178 seconds
OpenGL Dev Render, 2.5e-05 seconds
So, what is wrong?
- I believe that the vtkContour filter is being called, and if so, it isn't even logged. Please add logging.
- There are three filters I want to drill into above. One is the vtkSpyPlotReader. Please add a section for reading data in from file, and a second that is processing this data. Second is the vtkExtractCTHParts filter. Please give me an idea what is going on in here, such as how much time is spent on contour, how much is removing ghost cells, etc. Third is the first spcthredaer::GatherInformation. Is this read or processing time?
Next, lets change the pipeline slightly.
- Delete the ExtractCTHFilter.
- Add a Cell to Point filter.
- Add a Contour filter. Filter on Material Volume Fraction 1. Just use the reset button. Apply.
- Go to time step 10.
- Clear the timer log.
- Go to time step 11.
- Refresh the timer log.
I had to turn the Time Threshold to 0.01, to get rid of noise. That's OK. Here is what I get:
Execute vtkPVContourFilter id: 9339 (END event without matching START event)
Execute vtkPVContourFilter id: 9339, 0.01395 seconds
Execute vtkPVContourFilter id: 9339 (END event without matching START event)
Execute vtkGeometryRepresentationWithFaces id: 9531, 0.274198 seconds
vtkPVGeometryFilter::RequestData, 0.234535 seconds
vtkPVGeometryFilter::RequestCompositeData, 0.234481 seconds
vtkPVGeometryFilter::ExecuteCompositeDataSet, 0.223268 seconds
vtkPVView::Update (END event without matching START event)
RenderView::Update (END event without matching START event)
spcthreader::GatherInformation, 3.52453 seconds
CellDataToPointData::GatherInformation, 4.31269 seconds
Contour::GatherInformation, 0.097566 seconds
vtkSMRepresentationProxy::GetRepresentedDataInformation, 0.016231 seconds
Still Render, 0.037867 seconds
OpenGL Dev Render, 0.023415 seconds
Still Render (END event without matching START event)
Execute vtkPVContourFilter id: 9339 (END event without matching START event)
Execute vtkPVContourFilter id: 9339, 0.013752 seconds
Execute vtkPVContourFilter id: 9339, 0.014105 seconds
Execute vtkPVContourFilter id: 9339, 0.013434 seconds
<<snip>>
So, what is wrong?
- Error messages - End event without matching start.
- It would be nice if the contour filter gave us total time, rather than for ... what ... every fragment?
- This sure seemed to take more time than is logged.
- Again - the Gather Information in the spcthreader is useless. Ditto the CellDataToPointData.
- I cannot find a GatherInformation function in the object vtkCellDataToPointData. So, what does this "gather information" mean?
Edited by Utkarsh Ayachit