Page 1 of 1

Monitor load order and load times of lister plugins

Posted: 2021-07-01, 07:15 UTC
by funkymonk
Hello,

since we are currently discussing a lot about lister plugins (manual/automatic selection, etc.), there is one more feature that might be very helpful to debug and optimize the overall plugin configuration in TC:

When loading a file in lister/QV, several plugins might be tried until a working one is found. This leads to (avoidable) delays and in some cases TC even hangs/crashes if one of the plugins hangs/crashes. In both cases, it is difficult to see which plugin caused which delay or even the erroneous one. Thus, I recommend to capture the order in which the plugins were tried along with how much time was used by each plugin. This (and some more) information could be viewed in a simple table (accessible through the context menu or as a new entry in the Options menu).

Example:

Code: Select all

plugin      duration       success   totalLoadTime   detectString   <more information>
plugin1     20ms           -                         ...
plugin2     30ms           -                         ...
plugin3     10ms           YES       60ms            ...
plugin4     30ms           -                         ...
plugin5     20ms           YES       50ms            ...
plugin6     10ms           -                         ...
plugin1     22ms           -                         ...
plugin2     31ms           -                         ...
plugin3     15ms           YES       78ms            ...
In this example, 6 plugins will be tried cyclically for a file to be viewed. On initially opening lister/QV, plugin3 is the first that succeeds after 20+30+10=60ms. After pressing '4', plugin5 succeeds after 30+20=50ms. Pressing '4' again cycles over and plugin3 succeeds again after 78ms. This way, the list grows whenever '4' is pressed.

From the list, users and plugin developers can easily see for different files to be viewed:
  • plugin performance including load time jitter,
  • problems with certain plugins,
  • optimization potential for the TC plugin configuration (detect strings, order in "View by file type", etc.).
In case a plugin crashes TC entirely, the table can obviously not be shown.
And, I understand that implementing the table means some effort for Mr. Ghisler.

Therefore, some of the information could at least be added to the log files. E.g., "trying to use <plugin> on <file>" as the last log entry would clearly indicate which plugin has crashed TC.

BTW: Such log entries would also be useful for other plugin types (sometimes I encounter crashes when entering archives through packer plugins. Then, I never know which plugin has caused the crash.

What do you think?

BR
funkymonk

Re: Monitor load order and load times of lister plugins

Posted: 2021-07-01, 23:52 UTC
by petermad
I think the performance table is a little much to wish for, but I can support this part:
Therefore, some of the information could at least be added to the log files. E.g., "trying to use <plugin> on <file>" as the last log entry would clearly indicate which plugin has crashed TC.

BTW: Such log entries would also be useful for other plugin types (sometimes I encounter crashes when entering archives through packer plugins. Then, I never know which plugin has caused the crash.

Re: Monitor load order and load times of lister plugins

Posted: 2021-07-02, 05:15 UTC
by funkymonk
petermad wrote: 2021-07-01, 23:52 UTC I think the performance table is a little much to wish for [...]
Sure. Adding the table to the GUI means some work.
The idea just came up since we have implemented this feature for some of our applications that support plugins. It is very helpful for developers and might be so for developers/users of TC plugins as well.

Maybe some runtime/performance indicator(s) can still go into the log file?

Code: Select all

<plugin type>: [<plugin>] attempted on [<file>]
<plugin type>: [<plugin>] success on [<file>] in [<loadTimeInUs>] / [<totalLoadTimeInUs>]
<plugin type>: [<plugin>] fail on [<file>] in [<loadTimeInUs>]
The syntax and a fixed time base (e.g., us) would make it easy to extract relevant lines/information from long log files.
Regarding the example from some posts above, this would look like:

Code: Select all

L_plugin: [plugin1] attempted on [picture.jpg]
L_plugin: [plugin1] fail on [picture.jpg] in [20000]us
L_plugin: [plugin2] attempted on [picture.jpg]
L_plugin: [plugin2] fail on [picture.jpg] in [30000]us
L_plugin: [plugin3] attempted on [picture.jpg]
L_plugin: [plugin3] success on [picture.jpg] in [10000]us / [60000]us
The lines would look similar for different types of plugins (P_plugin, F_plugin, C_plugin).
And maybe logging (which itself causes some runtime overhead) could even be switchable (on/off/minimal) in the configuration.
"Minimal" means that only the attempts are logged -- this would always allow to see which plugin has caused a crash.

This is just an idea. I know is means some effort to implement.

Re: Monitor load order and load times of lister plugins

Posted: 2021-07-03, 05:12 UTC
by nsp
If it is for development only, you can implement a debug log inside plugin.

For tracking which plugin fails or hang it could be helpful in a dedicated plugin debug/log file. Structured information is always better specifically if you use dynamic log viewer with rules or post process with regExp. Christian should decide if it is helpful to have such information to speed up TC support when user have many plugins.