WARNING caused by execution_count > 10^19 (or negative!)

[Krysztophe]

(@rjuju: we've already discussed this 2 weeks ago but I went nowhere)

Powa : 3.1.1 pg_qualstats: 1.0.2 PG 9.6.5 on x86_64

• Symptom: in the logs, about every 8 hours :

  WARNING:  powa_take_snapshot(): function "powa_qualstats_aggregate" failed:
                     state  : 22003
                     message: bigint out of range
  ...
                     context: SQL statement "INSERT INTO powa_qualstats_constvalues_history (
         qualid, queryid, dbid, userid, coalesce_range, most_used, most_filtering, least_filtering, most_executed)
         SELECT * FROM powa_qualstats_aggregate_constvalues_current"
     PL/pgSQL function powa_qualstats_aggregate() line 9 at SQL statement
     SQL statement "SELECT powa_qualstats_aggregate()"
     PL/pgSQL function powa_take_snapshot() line 115 at EXECUTE
     SQL statement "SELECT powa_take_snapshot()"
  2017-10-17 07:14:46 CEST [2267]: [1502653-1] user=,db=,client= CONTEXT:  PL/pgSQL function powa_take_snapshot() line 124 at RAISE
     SQL statement "SELECT powa_take_snapshot()"

• Cause : In view powa_qualstats_aggregate_constvalues_current, the execution_count::bigint fails, because sum(powa_qualstats_constvalues_history_current.execution_count) > 9.10^18.

• In table powa_qualstats_constvalues_history_current, I find a few lines with execution_count = 6958710645500674048 (6,9.10^18).

• Amazingly, for the same queryid there are 3 NEGATIVE values for execution_count (such as -7079307180768231424 ).

• All of these lines come from the same 20 minutes-period almost a month ago.

• I'm wondering where these values come from. There is now nothing in pg_qualstats or pg_stat_statements for this queryid.

Only powa_statements contains this 5824-parameters query for the queryid:

queryid | 4254500497
query   | select anonymized as y0_ from ... this_ left outer join ... informatio1_ on this_.intirc_id=informatio1_.intirc_id where ( anonymized in ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20, $21, $22, $23, $24, $25, $26, $27, $28, $29, $30, $31, $32, 
...$999, $1000) 
or this_.intint_code_vision_apporteur in ($1001, ....      ...and so on...      $5823)) 
and informatio1_.anonymzed2 like $5824

• I'm stuck there. I'm not even sure the problem is in powa or pg_qualstats, and if the latest modifications in pg_qualstats 1.0.3 have anything to do with this.

• Assuming this is a one-time problem, must the lines about this queryid be manually purged from powa_qualstats_constvalues_history_current?

[rjuju]

I don't see obvious bug in pg_qualstats about execution_count counter. It's internally an uint64, so yes its representation as a bigint can be negative, and no check is done to make sure there's no overflow safeguard.

However, powa does reset pg_qualstats counters on each snapshot, so in order to get negative values in stored counters, you'd have to process more than 2^63 rows between two snapshots. so more than 3e16 row per second, which is quite unlikely :)

Can you confirm where you find negative execution count ? (pg_qualstats() output, or in powa_qualstats_constvalues_history_current or ?)

Does the 20 min interval show an unexpected high amount of activity in other tables ?

The easiest way to get though this (assuming you don't want to keep the data for debugging) would be to delete the apparently inconsistent rows. owever, since aggregation apparently didn't work since a month, doing this would probably result in a huge aggregation activity (the whole month) followed by a huge delete activity of the just aggregated data. If this is an option for you, it'd be way better to call powa_reset() and "loose" the current interval.

[Krysztophe]

• I confirm that these values are in powa_qualstats_constvalues_history_current
• Nothing special as far as I can tell on OPM : one backend, a small temp file (~30 Mb), no load, no writes. And the logs are gone.

[rjuju]

@Krysztophe after re reading this, I see that it's pg_qualstats 1.0.2. v1.0.3 includes https://github.com/powa-team/pg_qualstats/commit/e70233cbc035345fa49b4561215900aba78c1eba which is probably the source cause of this issue. I probably looked at current head instead of 1.0.2 when I checked this issue, and forgot about this fix.

I'd suggest to upgrade to 1.0.6, and do the required cleanup explained before, this should fix the problem.

There are too many open issues on the project, so I mark this one as closed, feel free to reopen it if the suggested fix doesn't work as expected.