VTK recently introduced a new logging infrastructure described in this post. This post acts as a brief summary of the implementation that we have under works on the ParaView side to access these new logging capabilities. The new logging infrastructure will ultimately replace the Timer Log available in ParaView to view execution times for various tasks.
Introduction
ParaView now provides an ability to developers to add entries to a log with helpful information that users may use to debug issues or identify bottlenecks. The logging framework supports logging with multiple verbosity levels, were -2
is used for ERROR messages, -1
for WARNING, 0
for INFO, and so on till 9
for TRACE (or MAX). When a message is logged, a verbosity level is provided. That message will then show up on log outputs configured for a level equal or greater to the message’s verbosity level. For example, by default the terminal output (stderr
) is configured to a verbosity level of INFO (0); thus any message logged with a level <= 0
including WARNING, ERROR, and INFO will be displayed on the terminal, while any message logged with a higher level will be hidden. Besides logging to the terminal, one can generate log outputs to files with different verbosity levels.
Except for error or warning messages, ParaView logs all its messages at the maximum (TRACE) level to avoid generating excessively verbose logs. Additionally, ParaView uses categories when logging messages with the ability to elevate verbosity level for chosen categories. For example, if you want to see all plugin related log messages on the terminal, one can simply change the verbosity level for the plugin category by setting the environment variable PARAVIEW_LOG_PLUGIN_VERBOSITY
to 0
or INFO. Currently, categories are provided for plugins, pipeline updates, data movement, rendering, and application level messages.
Command line arguments
All ParaView executables (paraview, pvserver, pvpython, etc.) support the following command line arguments that allow users to change verbosity level for the terminal and add file log outputs.
-v=
or --verbosity=
can be used to change the verbosity level for the messages posted to the terminal (stderr
). Default is 0
or INFO. Accepted values are a number between -2
and 9
or the ERROR, WARNING, TRACE, MAX, INFO, or OFF.
-l=
or --log=
can be used to add log output to a file. This option may be repeated to add multiple file logs. By default the verbosity level for the file output is 0
or INFO, however it can changed per option by adding a ,<level>
suffix after the filename e.g. to log all messages to file, one can use paraview -l=/tmp/allmessages.log,MAX. Any of the verbosity values accepted by the -v
can be used for the suffix.
Elevating verbosity level for a category
By default all ParaVIew messages are logged at the maximum verbosity level i.e. MAX or TRACE. During a run, it is possible to elevate the level for chosen category of log messages by using environment variables. Currently, following categories are supported (more may be added later):
-
PARAVIEW_LOG_DATA_MOVEMENT_VERBOSITY: These are messages related to data movement between processes that may happen when rendering, for example. Set the environment variable
PARAVIEW_LOG_DATA_MOVEMENT_VERBOSITY
to a verbosity value to elevate these messages to e.g.PARAVIEW_LOG_DATA_MOVEMENT_VERBOSITY=INFO
environment variable will show data movement messages on the terminal. -
PARAVIEW_LOG_RENDERING_VERBOSITY: These are messages related to rendering e.g. still render, interactive render, etc.
-
PARAVIEW_LOG_APPLICATION_VERBOSITY: This category is used for messages generated by the GUI and other user interface components, e.g. loading of settings and other configuration files etc.
-
PARAVIEW_LOG_PIPELINE_VERBOSITY: This category is used to log messages related to pipeline updates e.g. filter executions.
-
PARAVIEW_LOG_PLUGIN_VERBOSITY: Messages related to plugin loading are logged under this category.
As a example, here’s the output generated on launching ParaView and creating a Sphere
source when PARAVIEW_LOG_DATA_MOVEMENT_VERBOSITY was elevated to INFO. Notice how the log references the Sphere
source and entities related to it using the name that’s shown in the Pipeline Browser !
> env PARAVIEW_LOG_DATA_MOVEMENT_VERBOSITY=INFO ./bin/paraview
( 1.469s) [paraview ]vtkPVDataDeliveryManage:697 INFO| { check for delivery (interactive=false)
( 1.470s) [paraview ]vtkPVDataDeliveryManage:718 INFO| . none
( 1.470s) [paraview ]vtkPVDataDeliveryManage:697 INFO| } 0.000 s: check for delivery (interactive=false)
( 7.505s) [paraview ]vtkPVDataDeliveryManage:697 INFO| { check for delivery (interactive=false)
( 7.505s) [paraview ]vtkPVDataDeliveryManage:711 INFO| . needs-delivery: Sphere1(GeometryRepresentation)/DataAxesGrid/GridAxesRepresentation
( 7.505s) [paraview ]vtkPVDataDeliveryManage:711 INFO| . needs-delivery: Sphere1(GeometryRepresentation)/SelectionRepresentation/Geometry
( 7.505s) [paraview ]vtkPVDataDeliveryManage:711 INFO| . needs-delivery: Sphere1(GeometryRepresentation)/SurfaceRepresentation
( 7.505s) [paraview ]vtkPVDataDeliveryManage:697 INFO| } 0.000 s: check for delivery (interactive=false)
( 7.505s) [paraview ]vtkPVDataDeliveryManage:741 INFO| { full resolution data migration
( 7.505s) [paraview ]vtkPVDataDeliveryManage:759 INFO| . { move-data: Sphere1(GeometryRepresentation)/DataAxesGrid/GridAxesRepresentation
( 7.505s) [paraview ] vtkMPIMoveData.cxx:711 INFO| . . pass-through
( 7.506s) [paraview ]vtkPVDataDeliveryManage:759 INFO| . } 0.000 s: move-data: Sphere1(GeometryRepresentation)/DataAxesGrid/GridAxesRepresentation
( 7.506s) [paraview ]vtkPVDataDeliveryManage:759 INFO| . { move-data: Sphere1(GeometryRepresentation)/SelectionRepresentation/Geometry
( 7.506s) [paraview ] vtkMPIMoveData.cxx:711 INFO| . . pass-through
( 7.506s) [paraview ]vtkPVDataDeliveryManage:759 INFO| . } 0.000 s: move-data: Sphere1(GeometryRepresentation)/SelectionRepresentation/Geometry
( 7.506s) [paraview ]vtkPVDataDeliveryManage:759 INFO| . { move-data: Sphere1(GeometryRepresentation)/SurfaceRepresentation
( 7.506s) [paraview ] vtkMPIMoveData.cxx:711 INFO| . . pass-through
( 7.506s) [paraview ]vtkPVDataDeliveryManage:759 INFO| . } 0.000 s: move-data: Sphere1(GeometryRepresentation)/SurfaceRepresentation
( 7.506s) [paraview ]vtkPVDataDeliveryManage:741 INFO| } 0.001 s: full resolution data migration
Logging with multiple processes
When running with MPI, the process names get suffixed by the rank number, thus making it easier to identify which message is coming from which rank e.g.
> env PARAVIEW_LOG_PLUGIN_VERBOSITY=INFO mpirun -np 2 ./bin/pvserver
...
( 0.175s) [pvserver.0 ] vtkPVPluginLoader.cxx:270 9| appDir: /home/utkarsh/Kitware/ParaView3/ParaViewBin-Qt5/bin/plugins
( 0.175s) [pvserver.1 ] vtkPVPluginLoader.cxx:270 9| appDir: /home/utkarsh/Kitware/ParaView3/ParaViewBin-Qt5/bin/plugins
( 0.175s) [pvserver.0 ] vtkPVPluginLoader.cxx:270 9| appDir: /home/utkarsh/Kitware/ParaView3/ParaViewBin-Qt5/bin/plugins
( 0.175s) [pvserver.0 ] vtkPVPluginLoader.cxx:296 9| Loading Plugins from standard PLUGIN_PATHS
/home/utkarsh/Kitware/ParaView3/ParaViewBin-Qt5/bin/plugins
( 0.175s) [pvserver.1 ] vtkPVPluginLoader.cxx:270 9| appDir: /home/utkarsh/Kitware/ParaView3/ParaViewBin-Qt5/bin/plugins
( 0.175s) [pvserver.1 ] vtkPVPluginLoader.cxx:296 9| Loading Plugins from standard PLUGIN_PATHS
...
Also, if a file log output was specified using -l=
or --log=
option then each MPI rank will write to separate file by suffixing the filename with .[rank-number]. Thus mpirun -np 2 ./bin/pvserver -l=/tmp/messages.log
will generate /tmp/messages.log.0
and /tmp/messages.log.1
log files.
GUI
Currently, there is no graphical interface to access the log. That may be added in future, if needed.
Any feedback, suggestions, comments are welcome as always. This is slated to be included in ParaView 5.7 release.