[FEATURE] Show per-script hook execution time for performance profiling

[luginf]

Is your feature request related to a problem? Please describe.

When multiple scripts are installed, it is currently impossible to identify which one is causing slowdowns without disabling them one by one. A lightweight profiling mechanism would make it much easier to diagnose performance issues.

Describe the solution you'd like

Wrap each scripting hook invocation (e.g. noteToMarkdownHtmlHook, handleNoteTextFileNameHook, customActionInvoked, …) with a QElapsedTimer on the C++ side. When execution time exceeds a configurable threshold (or unconditionally in a debug/profiling mode), log a warning such as:

[script profiler] my-script :: noteToMarkdownHtmlHook took 42 ms

Optionally, expose an aggregated summary (total time per script per hook) in the script settings panel or in the log window.

• noteToMarkdownHtmlHook is called on every keystroke in live preview — even a mildly expensive script causes visible lag.
• Users with many scripts installed have no way to pinpoint the offending one without tedious manual bisection.
• The change is self-contained: a QElapsedTimer around each existing hook dispatch call, with a threshold guard to avoid log noise.

Describe alternatives you've considered

• A QOwnNotes script cannot profile other scripts: the scripting API exposes no inter-script communication or CPU metrics.
• OS-level profiling (perf, valgrind) works but cannot attribute time to individual scripts by name.

[pbek]

Could be a good debugging tool.

execution time exceeds a configurable threshold

That would be very different for each scripting function / hook and differ from machine to machine. 🤔

[pbek]

26.5.15

• Added per-script hook execution time profiling for performance diagnostics
  (for #3620)
  • When debug logging is enabled all hook invocation times are logged
    unconditionally via qDebug()
  • When debug logging is not active, only hook invocations that exceed a
    configurable threshold are logged as warnings
  • The threshold (default 500 ms) can be configured in the new
    Script hook execution time warning threshold spinbox in the
    Debug options settings page
  • External-process scripting functions (startDetachedProcess,
    startSynchronousProcess) are intentionally excluded from profiling
    because their runtime is dominated by the child process, not the
    scripting engine
  • Log messages have the form: [script profiler] <script-name> :: <hookName> took <N> ms

[pbek]

There now is a new release, could you please test it and report if it works for you?

[luginf]

There now is a new release, could you please test it and report if it works for you?

thank you very much, I'm testing it right now. It will be useful to detect strange or excessive behaviors. For example, I've seen those lines:

[May 24 23:37:07] [debug]: [script profiler] "@tag tagging in note text (experimental)" :: "noteTaggingHook" took 1 ms
[May 24 23:37:07] [debug]: [script profiler] "@tag tagging in note text (experimental)" :: "noteTaggingHook" took 0 ms

500 times, at the same time (between 23:37:06 and 23:37:07). Even if it's only 0 or 1 ms, it might lead to 1/2 second lag.