Re: pg_stat_statements: calls under-estimation propagation - Mailing list pgsql-hackers

On Thu, Oct 10, 2013 at 10:49 AM, Alvaro Herrera
<alvherre@2ndquadrant.com> wrote:
> Daniel Farina escribió:
>> On Thu, Oct 10, 2013 at 7:40 AM, Fujii Masao <masao.fujii@gmail.com> wrote:
>
>> > In my test, I found that pg_stat_statements.total_time always indicates a zero.
>> > I guess that the patch might handle pg_stat_statements.total_time wrongly.
>> >
>> > +        values[i++] = DatumGetTimestamp(
>> > +            instr_get_timestamptz(pgss->session_start));
>> > +        values[i++] = DatumGetTimestamp(
>> > +            instr_get_timestamptz(entry->introduced));
>> >
>> > These should be executed only when detected_version >= PGSS_TUP_LATEST?
>>
>> Yes. Oversight.
>
> Hmm, shouldn't this be conditional on a new PGSS_TUP_V1_2?  I mean, if
> later somebody patches pgss to have a PGSS_TUP_V2 or V1_3 and that
> becomes latest, somebody running the current definition with the updated
> .so will no longer get these values.  Or is the intention that
> PGSS_TUP_LATEST will never be updated again, and future versions will
> get PGSS_TUP_REALLY_LATEST and PGSS_TUP_REALLY_LATEST_HONEST and so on?
> I mean, surely we can always come up with new symbols to use, but it
> seems hard to follow.
>
> There's one other use of PGSS_TUP_LATEST here which I think should also
> be changed to >= SOME_SPECIFIC_VERSION:
>
> +       if (detected_version >= PGSS_TUP_LATEST)
> +       {
> +           uint64 qid = pgss->private_stat_session_key;
> +
> +           qid ^= (uint64) entry->query_id;
> +           qid ^= ((uint64) entry->query_id) << 32;
> +
> +           values[i++] = Int64GetDatumFast(qid);
> +       }

I made some confusing mistakes here in using the newer tuple
versioning.  Let me try to explain what the motivation was:

I was adding new fields to pg_stat_statements and was afraid that it'd
be hard to get a very clear view that all the set fields are in
alignment and there were no accidental overruns, with the problem
getting more convoluted as more versions are added.

The idea of PGSS_TUP_LATEST is useful to catch common programmer error
by testing some invariants, and it'd be nice not to have to thrash the
invariant checking code every release, which would probably defeat the
point of such "oops" prevention code.  But, the fact that I went on to
rampantly do questionable things PGSS_TUP_LATEST is a bad sign.

By example, here are the two uses that have served me very well:
   /* Perform version detection */   if (tupdesc->natts == PG_STAT_STATEMENTS_COLS_V1_0)       detected_version =
PGSS_TUP_V1_0;  else if (tupdesc->natts == PG_STAT_STATEMENTS_COLS_V1_1)       detected_version = PGSS_TUP_V1_1;   else
if(tupdesc->natts == PG_STAT_STATEMENTS_COLS)       detected_version = PGSS_TUP_LATEST;   else   {       /*        *
Couldn'tidentify the tuple format.  Raise error.        *        * This is an exceptional case that may only happen in
bizarre       * situations, since it is thought that every released version        * of pg_stat_statements has a
matchingschema.        */       ereport(ERROR,               (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE),
       errmsg("pg_stat_statements schema is not supported "                       "by its installed binary")));   } 

And

#ifdef USE_ASSERT_CHECKING       /* Check that every column appears to be filled */       switch (detected_version)
 {               case PGSS_TUP_V1_0:                       Assert(i == PG_STAT_STATEMENTS_COLS_V1_0);
   break;               case PGSS_TUP_V1_1:                       Assert(i == PG_STAT_STATEMENTS_COLS_V1_1);
          break;               case PGSS_TUP_LATEST:                       Assert(i == PG_STAT_STATEMENTS_COLS);
              break;               default:                       Assert(false);       } 
#endif

Given that, perhaps a way to fix this is something like this patch-fragment:

"""{ PGSS_TUP_V1_0 = 1, PGSS_TUP_V1_1,
- PGSS_TUP_LATEST
+ PGSS_TUP_V1_2} pgssTupVersion;

+#define PGSS_TUP_LATEST PGSS_TUP_V1_2
"""

This way when a programmer is making new tuple versions, they are much
more likely to see the immediate need to teach those two sites about
the new tuple size.  But, the fact that one does not get the
invariants updated in a completely compulsory way may push the value
of this checking under water.

I'd be sad to see it go, it has saved me a lot of effort when
returning to the code after a while.

What do you think?

> The instr_time thingy being used for these times maps to
> QueryPerformanceCounter() on Windows, and I'm not sure how useful this
> is for long-term time tracking; see
> http://stackoverflow.com/questions/5296990/queryperformancecounter-and-overflows#5297163
> for instance.  I think it'd be better to use TimestampTz and
> GetCurrentTimestamp() for this.

Ah. I was going to do that, but thought it'd be nice to merely push
down the already-extant Instr struct in most cases, as to get the
'start' time stored there for "free."  But if it can't work on
Windows, maybe trying to spare the code from a new abstraction to
learn or argument list creep is ending in failure this time.

> Just noticed that you changed the timer to struct Instrumentation.  Not
> really sure about that change.  Since you seem to be using only the
> start time and counter, wouldn't it be better to store only those?
> Particularly unsure about passing INSTRUMENT_ALL to InstrAlloc().

Yeah, I was unsure about that too.

The motivation was that I need one more piece of information in
pgss_store (the absolute start time).  I was going to widen the
argument list, but it was looking pretty long, so instead I was
thinking it'd be more concise to push the entire, typically extant
Instrumentation struct pointer down.

There is that one ugly site you noticed where I had to make a new,
zero-valued Instrumentation value and its pointer to do that, and I
also found was that I needed guards for NULL Instrumentation values,
so maybe this experiment was a failure.

I considered ginning up a new Instr on the stack as a
micro-optimization, but figured getting a full-blown allocated
zero-valued Instr by re-using the API was clean enough for the
purpose.

It looks like the concern about Windows may demand that re-using the
"start" time out of Instr is not a good idea, and that was the whole
point of that attempt.