PSQL and SQL profiler

[asfernandes]

No description provided.

[asfernandes]

Are there any objections to integrate this in master, or anything yet to discuss?

[romansimakov]

In firebird-devel we talked about an ability to profile other connections. Has it been added or are you going to add it later?

[asfernandes]

In firebird-devel we talked about an ability to profile other connections. Has it been added or are you going to add it later?

I think this change would not invalidate the current design, so I think it does not make much sense to continue adding features before an initial integration and lack of feedback on what we have now.

[romansimakov]

In firebird-devel we talked about an ability to profile other connections. Has it been added or are you going to add it later?

I think this change would not invalidate the current design, so I think it does not make much sense to continue adding features before an initial integration and lack of feedback on what we have now.

I don't mind if so

[dyemanov]

I'd prefer the default plugin to be used without naming in START_SESSION (for example, declare NULL as a default value). It could be done via DefaultProfilerPlugin option in firebird.conf, for example. Alternatively, we may have ProfilerPlugin option in firebird.conf (similar to TracePlugin = fbtrace) that substitutes the missing plugin name in START_SESSION to any specified plugin (not only the default one). One may still specify the plugin name explicitly in START_SESSION, if necessary.

[dyemanov]

Once we support profiling other connections (I agree this is a top priority feature), should we extend START_SESSION with a new parameter (ATTACHMENT_ID DEFAULT CURRENT_ATTACHMENT) or some new function will be introduced?

[dyemanov]

While I don't mind CREATE_SESSION and FINISH_SESSION routine names, I'd suggest to rename SESSION_ID columns inside tables to PROFILE_ID. Having SESSION_ID and ATTACHMENT_ID side to side looks somewhat ambiguous, considering we have SESSION_ID and USER_SESSION meaning attachments in RDB$GET_CONTEXT, and also considering the SQL specification having SESSION_USER where session also means an attachment.

[dyemanov]

Why FBPROF$ prefix for tables/views instead of just PROF$? We're Firebird anyway, so what's the point.

[dyemanov]

Given the default profiler plugin is supposedly to be really usable (not just a draft example of how things should be coded), why its tables/views are created dynamically rather than being part of ODS? Are they expected to change significantly with time?

[dyemanov]

I really miss timings (count/min/max/total) for statements as a whole. It would be inconvenient to measure them with some external tools and then look into PROF$ tables/views for details, it would be more handy to have everything in a single place. Especially if we speak about multiple executions of a single prepared/cached statement.

[dyemanov]

I've attempted to collect execution times in the past, but wanted to split them into total/cpu/wait parts, with the wait part being also detailed (I/O, lock, latch, pause, etc). Given that extra measurements are not always dirty cheap, I had a doubt they should be presented via MON$ tables unconditionally. Now it looks like it could be integrated with your profiler design after it's committed and thus measured on demand. But the question is how deep we need to dive into the CPU time. Is it OK to calculate it as (total - wait) (or leave this calculation up to users), or do we want to see real CPU time and possibly deal with some delta (total - wait - cpu) that remains unknown. And if we need real CPU time, do we want user/kernel times? All these things complicate the implementation and make it somewhat platform-dependent.

[dyemanov]

I feel the profiler package also needs a routine SET_FLUSH_INTERVAL that does flushing automagically, based on timer. Zero (default) means manual flushing, as designed currently.

[aafemt]

It could be done via DefaultProfilerPlugin option in firebird.conf, for example. Alternatively, we may have ProfilerPlugin option in firebird.conf (similar to TracePlugin = fbtrace)

Talking about configuration: because profiling is entirely engine-related, I'd say that this setting should belong to Engine14.conf, not firebird.conf.

[asfernandes]

Given the default profiler plugin is supposedly to be really usable (not just a draft example of how things should be coded), why its tables/views are created dynamically rather than being part of ODS? Are they expected to change significantly with time?

1. Then it's not really plugin design
2. It would require many code to make backup and restore of them work
3. It would not support primary and foreign keys

[asfernandes]

Why FBPROF$ prefix for tables/views instead of just PROF$? We're Firebird anyway, so what's the point.

My idea was to have a FB namespace to differentiate things from users objects, as they can also use the dollar sign.

But since it's new name convention, I would not have a problem to change it.

We also have PLG$* tables, so maybe we should name them PLG$PROF*?

[asfernandes]

I really miss timings (count/min/max/total) for statements as a whole. It would be inconvenient to measure them with some external tools and then look into PROF$ tables/views for details, it would be more handy to have everything in a single place. Especially if we speak about multiple executions of a single prepared/cached statement.

How these stored timings would be different than aggregate the request-based timings per STATEMENT_ID?

[asfernandes]

I feel the profiler package also needs a routine SET_FLUSH_INTERVAL that does flushing automagically, based on timer. Zero (default) means manual flushing, as designed currently.

Data (even when flushed) is stored as part of user transaction, that may be rolled back later.

I do not see a way that automatic flush would work with this or would be less confusing than manually flush the data before read.

But this could be useful in the case of profiling others connections.

[dyemanov]

We also have PLG$* tables, so maybe we should name them PLG$PROF*?

This looks good to me.

[dyemanov]

Data (even when flushed) is stored as part of user transaction, that may be rolled back later.

Automatic flushing could behave like it's executed in autonomous transaction. Rollback will surely not be possible, but one may always delete the rows manually. This should be well-documented, of course.

[dyemanov]

How these stored timings would be different than aggregate the request-based timings per STATEMENT_ID?

They cannot be aggregated from RECORD_SOURCE_STATS, as time may also be spent between cursor operations. Perhaps it could be aggregated from PSQL_STATS, but only for PSQL routines. Imagine I execute INSERT FROM SELECT and 90% of time is spent inside VIO_store(), how could I get the total execution time for my statement? What about non-PSQL procedures/functions?

[AlexPeshkoff]

On 5/1/22 19:02, Adriano dos Santos Fernandes wrote: Given the default profiler plugin is supposedly to be really usable (not just a draft example of how things should be coded), why its tables/views are created dynamically rather than being part of ODS? Are they expected to change significantly with time? 1. Then it's not really plugin design

I want to explicitly agree with Adriano here. I see no reasons for one particular plugin to have required for it tables in ODS.

[asfernandes]

I've implemented profiling of others attachments with this commit set. The semantics of it is documented in the readme.

To make things not confusing, user's transaction is not passed to plugins anymore and flush always starts its own transaction.

[asfernandes]

How these stored timings would be different than aggregate the request-based timings per STATEMENT_ID?

They cannot be aggregated from RECORD_SOURCE_STATS, as time may also be spent between cursor operations. Perhaps it could be aggregated from PSQL_STATS, but only for PSQL routines. Imagine I execute INSERT FROM SELECT and 90% of time is spent inside VIO_store(), how could I get the total execution time for my statement? What about non-PSQL procedures/functions?

I think we need TOTAL time of requests (as stored in PLG$PROF_REQUESTS) which is valid for SQL and PSQL.

Then it's possible to calculate MIN/MAX per STATEMENT (as stored in PLG$PROF_STATEMENTS).

[asfernandes]

I've attempted to collect execution times in the past, but wanted to split them into total/cpu/wait parts, with the wait part being also detailed (I/O, lock, latch, pause, etc). Given that extra measurements are not always dirty cheap, I had a doubt they should be presented via MON$ tables unconditionally. Now it looks like it could be integrated with your profiler design after it's committed and thus measured on demand. But the question is how deep we need to dive into the CPU time. Is it OK to calculate it as (total - wait) (or leave this calculation up to users), or do we want to see real CPU time and possibly deal with some delta (total - wait - cpu) that remains unknown. And if we need real CPU time, do we want user/kernel times? All these things complicate the implementation and make it somewhat platform-dependent.

AFAIK there is no way to directly get the "wait time" from the OS. It's the elapsed time minus the thread's CPU time (user + kernel).

I think we can pass the elapsed and total thread's CPU time. The helper views could also calculate the total wait time.

We should decide if the APIs that currently receives only uint64 runTime would get a new uint64 cpuTime parameter, hence will not be extensible.

Or if we would need to add another interface which would be extensible and plugin writers would call its methods to get timings. The downside of this is that it will be slower.

[dyemanov]

Yes, no way to get wait time from the system. But we can measure "logical waits" ourselves in most points where we checkout from the engine. Some of them won't be honest (IO wait time will actually be IO CPU time when reads are performed from filesystem cache, for example), but this is OK as they're expected to be short and unlikely to be noticeable as "top" waits. If the CPU time is also measured, then we could calculate "wait" as "total time - CPU time" and it should be more or less real, but I doubt it gonna be useful. So I'm somewhat skeptical in whether we really need CPU time...

[asfernandes]

Anyone see a blocking point to have this merged in master?

[AlexPeshkoff]

On 5/4/22 11:39, Vlad Khorsun wrote: We also have |PLG$*| tables, so maybe we should name them |PLG$PROF*|? This looks good to me. What does it means ? PLG == ???

That's just prefix like RDB$, see PLG$SRP_USERS in sec db.

[asfernandes]

On 04/05/2022 07:49, Vlad Khorsun wrote: So, if user call RDB$PROFILER.START_SESSION and RDB$PROFILER.FLUSH in the same (own) transaction, profiler will create metadata and attempt to use it (to INSERT something) in the same transaction ?

No, and actually things happens a bit different. The default plugin uses the transaction from startSession to query a sequence to make the session id. There is the init method. Init receives a attachment and transaction. The default plugin uses the attachment to start a new transaction to create the metadata. Init is called by engine once per database/plugin when a profiler session is about to be created. Adriano

[pavel-zotov]

@@@ QA issue @@@
Test verifies only example from doc/sql.extensions/README.profiler.md
More complex checks will be implementer later.