1464310 - Add profiler stack labels which contain the sql string when statements are executed or stepped

Status: RESOLVED FIXED

(Toolkit :: Storage, enhancement, P3)

Description

[Markus Stange [:mstange]]

This can make profiles more useful if the storage threads are profiled.

Comment 1

[Markus Stange [:mstange]]

Attachment: Bug 1464310 - Add profiler stack labels which contain the sql string when statements are executed or stepped.

Review commit: https://reviewboard.mozilla.org/r/246656/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/246656/

Comment 2

[Andrew Sutherland [:asuth] (he/him)]

Depending on the use-case, it might make sense to turn on the sqlite3 trace functionality like we do when MOZ_LOG is cranked up to debug: https://searchfox.org/mozilla-central/source/storage/mozStorageConnection.cpp#795 which traces at https://searchfox.org/mozilla-central/source/storage/mozStorageConnection.cpp#200

Note that many slow things (Places ;) may use async threads, which currently get boring and emergent random thread names, which may be a problem for the profiler unless it wants to activate for all async storage threads.

Comment 3

[Andrew Sutherland [:asuth] (he/him)]

Uh, and the advantage over the current approach is that the SQLite trace mechanism is able to give insight into nested statements and triggers that may fire.

Comment 4

[Marco Bonardo [:mak]]

(In reply to Andrew Sutherland [:asuth] from comment #2)
> Depending on the use-case, it might make sense to turn on the sqlite3 trace
> functionality like we do when MOZ_LOG is cranked up to debug

Are you suggesting to expose a way for the profiler to enable sqlite tracing on demand?
Doesn't sqlite_trace add quite some overhead, that is the opposite of what we want when profiling?
Am I misunderstanding your proposal?

Comment 5

[Andrew Sutherland [:asuth] (he/him)]

Elaborating on my use-case comment, I think there's probably 2 main use-cases I could see:
1. Finding out where SQL use is happening to aid in understanding what a thread or the system is getting up to at a high-level. You can see when the main thread is doing SQL (eek!) or specific other threads.
2. Understanding what's taking so long with the SQL.

This patch is use-case 1, my comment 2 is talking about use-case 2.

I assume there's some motivation behind comment 0 that might shed light on which is more useful as it relates to overhead.  As a storage peer, use-case 1 is probably enough to refer people to this component, but I'd want to see a use-case 2 profile if I was going to give feedback.  (Realistically speaking, it would be you giving feedback though ;).

In terms of overhead, I understand these probes to be generating labels that are only captured if the sample happens when they're on the stack, as opposed to profile markers which end up getting logged either way.  (Disclaimer: my understanding of markers may be very out-of-date, last time I checked I think they got latched to the next sample that got logged.)  I think this might mitigate some of the concern about overhead.  I think any historical overhead might be due to 2 things:
- PR_LOG to stdout/stderr was very verbose because there was a lot going on, and we'd output every time (at marker as opposed to sample), and there was potentially the issue of the terminal UI slowing things down due to backpressure.  (I believe libvte used to want to paint everything as it came in?)
- I believe sqlite3_trace liked to fully expand the SQL including interpolating parameters for every call, which was a lot of string processing overhead.  sqlite3_trace_v2 (https://www.sqlite.org/c3ref/trace_v2.html) has improved this by requiring the trace function to explicitly request the expanded form via sqlite3_expanded_sql  (https://www.sqlite.org/c3ref/expanded_sql.html) as documented at https://www.sqlite.org/c3ref/expanded_sql.html.

But again, this depends on the motivation.  I agree the current set of patches is quite useful and without doubt less overhead than enabling tracing.  (The question is how bad is the tracing overhead.)  I have no problem with landing these as-is and considering what I'm talking about as a follow-up should-the-need-arise.  (We just need to make sure the bug doesn't end up inactive for 1 year! ;)

Comment 6

[Marco Bonardo [:mak]]

I think there are too many unknowns yet, and point 1 sounds like an improvement of the status-quo, over which we could still always improve, since this patch is not going to create technical debt.
I'm mostly worried of any overhead sqlite_trace_v2 may add, we already have perf problems, I'd not want to pile up more. And until someone has good reasons to investigate that overhead, I'm not willing to just ignore a possible problem.

Comment 7

[Marco Bonardo [:mak]]

Comment on attachment 8980484 [details]
Bug 1464310 - Add profiler stack labels which contain the sql string when statements are executed or stepped.

https://reviewboard.mozilla.org/r/246656/#review254398

::: storage/mozStorageConnection.cpp:1170
(Diff revision 1)
>  int
>  Connection::stepStatement(sqlite3 *aNativeConnection, sqlite3_stmt *aStatement)
>  {
> +  AUTO_PROFILER_LABEL_DYNAMIC_CSTR("Connection::stepStatement", OTHER,
> +                                   ::sqlite3_sql(aStatement));
> +

please move this after the MOZ_ASSERT

::: storage/mozStorageConnection.cpp:1282
(Diff revision 1)
>  
>  
>  int
>  Connection::executeSql(sqlite3 *aNativeConnection, const char *aSqlString)
>  {
> +  AUTO_PROFILER_LABEL_DYNAMIC_CSTR("Connection::executeSql", OTHER, aSqlString);

please move this after the MISUSE check

Comment 8

[Markus Stange [:mstange]]

Comment on attachment 8980484 [details]
Bug 1464310 - Add profiler stack labels which contain the sql string when statements are executed or stepped.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/246656/diff/1-2/

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9d570f91ea5a
Add profiler stack labels which contain the sql string when statements are executed or stepped. r=mak

Comment 10

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/9d570f91ea5a