New logging support in ParaView

utkarsh.ayachit · February 15, 2019, 9:02pm

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.

Kenneth_Moreland · February 17, 2019, 3:49pm

I’m not super excited about this change, particularly with the loss of the GUI. The current (5.6 and previous) log window is simple to use and reasonably effective. Moving to an entirely command-line/environment-variable/file interface seems like a step way back. Command line arguments and environment variables are pain to set up in Windows and damn near impossible on Mac. Setting command lines for pvserver can be challenging if you are relying on an installation provided by a system administrator. Even if you can do all that, it still means you have to shut everything down and start ParaView up again any time you want to know how fast something went.

At a minimum, the logging options should be selectable through the GUI. That seems like a pretty trivial thing to implement.

It would also be much nicer if the log information were funneled to a buffer to be potentially displayed in a dialog box in the GUI. You could call it something like Timer Log. Even better, parse the log data to provide prettier display. (And have a nice save log button. That’s the easy part.)

utkarsh.ayachit · February 17, 2019, 3:55pm

That’s not true. Timer Log in its present form persists and will continue to exist until the new functionality can fully replace it.

In this first iteration, I just don’t have time to add the GUI stuff hence it’s being deferred until later.

Another thing to note, this logging is intended for more than just how long a filter takes?. For example, while debugging #18741, I simply add log lines to the spreadsheet view to figure out which blocks are being requested when and I can debug it very easily. Now one could say I could have always used TimerLog for the same, but Timerlog didn’t have support for levels, which means any log items I add would always be processed and added to the log. Accumulation of a lot of such log line would invariably impact the runtime. The new logging infrastructure doesn’t evaluate log arguments unless the some log output requests the level (or higher) used for logging that item.

What we have here is a backbone. The GUI is indeed important – but for it to be useful, it must indeed be more than what the timer log GUI currently is. I was looking at various log viewer tools. A nice interface that shows lines from all processes as they are generated nicely with coloring etc etc is indeed a good idea. But doing it without adding too much runtime cost needs careful consideration and hence deferring it until later.