Subject: Re: Database stats ( pg_stat_database.stats_reset ) get reset on daily basis - why?

From: Steeve Boulanger <[email-masked]>
Date: Thu, 21 Nov 2024 14:57:58 -0600

> Please reply to list also.

My apologies - I thought I did a "Reply all", but apparently not. I'm a
little bit of a noob with email distrib lists.

> 1) What is log_min_error_statement set to?

          name           | setting | pending_restart
-------------------------+---------+-----------------
 log_min_error_statement | error   | f

> 2) Did you reload the server when changing?:

yes - pg_reload_conf()

-Steeve

On Thu, Nov 21, 2024 at 2:49 PM Adrian Klaver <[email-masked]>
wrote:

> On 11/21/24 12:34, Steeve Boulanger wrote:
>
> Please reply to list also.
>
> Ccing list.
>
>
> > Thanks Adrian for taking the time to respond. I will review the
> > documentation once more, just in case I missed anything.
> >
> > My apologies - I forgot to mention in my original post, that our last
> > cluster shutdown was over 15 days ago, thus an "unclean"
> > shutdown would not explain these daily stats reset that we are seeing.
> > It might also be relevant to mentioned
>
> Then something is resetting the statistics.
>
> 1) What is log_min_error_statement set to?
>
> 2) Did you reload the server when changing?:
>
> log_min_duration_statement | 0
> log_statement              | all
>
> >
> > -Steeve
> >
> >
>
> --
> Adrian Klaver
> [email-masked]
>
>

---

From: Adrian Klaver <[email-masked]>
Date: Thu, 21 Nov 2024 13:12:07 -0800

>            name           | setting | pending_restart

All I can think to do is look at the logs  around the stats_reset times 
for the databases and see if there is anything relevant.

---

From: Ron Johnson <[email-masked]>
Date: Thu, 21 Nov 2024 16:29:47 -0500

> for the databases and see if there is anything relevant.

Also, "SELECT pg_postmaster_start_time();" to show the *real* Postgresql
start time, instead of what you think it is.

-- 
Death to <Redacted>, and butter sauce.
Don't boil me, I'm still alive.
<Redacted> lobster!

---

From: Steeve Boulanger <[email-masked]>
Date: Thu, 21 Nov 2024 15:31:16 -0600

> for the databases and see if there is anything relevant.

That was already done, but nothing relevant was found unfortunately.

-Steeve

---

From: Steeve Boulanger <[email-masked]>
Date: Thu, 21 Nov 2024 15:33:36 -0600

Hello Ron,

Yes you're right - I should have been more explicit.

[local]:5432 postgres@postgres=# select current_timestamp -
pg_postmaster_start_time() as uptime;
         uptime
-------------------------
 15 days 10:03:44.048383

-Steeve

---

From: Adrian Klaver <[email-masked]>
Date: Thu, 21 Nov 2024 14:32:06 -0800

> That was already done, but nothing relevant was found unfortunately.

Unless it was not recognized as relevant. Since for the time being I am 
eliminating magic as the cause, something concrete is causing this and 
it should be leaving a trace. In your post you had this affecting 77 out 
of 157 databases in the cluster.

1) Do the 77 share some trait the other 80 don't.

2) Do the OS system logs reveal anything?

3) What was happening in the databases just prior to the time the stats 
reset?

4) Do you have external tools accessing these databases?

5) Is the cluster directly open to the world?

> 
> -Steeve
> 
> On Thu, Nov 21, 2024 at 3:12 PM Adrian Klaver <[email-masked] 
> <mailto:[email-masked]>> wrote:
> 
>      >  > Please reply to list also.
>      >
>      >  > 1) What is log_min_error_statement set to?
>      >
>      >  > 2) Did you reload the server when changing?:
>      >
>      > yes - pg_reload_conf()
> 
>     [email-masked] <mailto:[email-masked]>
>

---

From: Steeve Boulanger <[email-masked]>
Date: Thu, 21 Nov 2024 17:50:13 -0600

>  1) Do the 77 share some trait the other 80 don't.

No pattern found yet .. but still verifying a few things

> 2) Do the OS system logs reveal anything?

Nothing found in syslog

reset?

Here's an example (log extracts) for a stats reset occurrence:

select datname, stats_reset, now()-stats_reset as since_reset
from pg_stat_database
where ( now()-stats_reset ) < interval '1 day'
order by 3  limit 1;

    datname     |          stats_reset          |   since_reset
----------------+-------------------------------+-----------------
 MyDB           | *2024-11-21 13:48:34.332*785+00 | 00:00:22.266304

<--LOGS-->
2024-11-21 13:48:34.324 UTC pid=[322035][2]  db=[MyDB] usr=[user1]
client=[host1] app=[[unknown]]LOG:  connection authorized: user=user1
database=MyDB applicatio
n_name=app1 <..>

<.. no calls at "2024-11-21 13:48:34.332" - WHY?? ..>

2024-11-21 13:48:34.336 UTC pid=[322035][3]  db=[MyDB] usr=[user1]
client=[host1] app=[app1]LOG:  duration: 1.071 ms  parse <unnamed>: SELECT
<..>
<--LOGS-->

As you can see from above, the stats for MyDB were reset at  ".332" . The
only logs before/after for the db was the connection (at .324), and then
the parse (at .336).  NB: I also checked the logs at ".333" in case there
would have been a rounding up, but nothing relevant was found. With that
said, I only verified one occurence - tomorrow I'll check a few more just
to validate.

> 4) Do you have external tools accessing these databases?

We have internal micro-services accessing the databases, as well as a
monitoring tool (Netdata), and some of the Devs use pgAdmin. I discarded
the scenario where someone would inadvertently do a "pg_stat_reset" via
pgAdmin, just because a lot of databases have their stats reset within a
short period of time.

On the other hand, Netdata does connect to most (if not all) databases
frequently by its nature - so as a test, I stopped the Netdata service
today to see if tomorrow we're still seeing the stats reset or not. I can
report back tomorrow on this.

> 5) Is the cluster directly open to the world?

No. It's an on-premise installation. Only local applications can connect to
it.

-Steeve

---

From: Adrian Klaver <[email-masked]>
Date: Fri, 22 Nov 2024 09:18:31 -0800

>      datname     |          stats_reset          |   since_reset

What is the [2] referring to?

> <.. no calls at "2024-11-21 13:48:34.332" - WHY?? ..>

My guess is the difference in time it takes to log the action and set 
the log timestamp. Whereas the stats_reset value is the timestamp when 
the stats system actually did the reset.

> client=[host1] app=[app1]LOG:  duration: 1.071 ms parse <unnamed>: 
> SELECT <..>

The above is some garden variety select?

---

From: Steeve Boulanger <[email-masked]>
Date: Sat, 23 Nov 2024 07:06:30 -0600

> What is the [2] referring to?

Number of the log line for each session or process, starting at 1

> the stats system actually did the reset.

Very plausible. I thought the same too.

> The above is some garden variety select?

Not 100% sure what the expression "garden variety select" means lol, but
I'll take a guess that it means an "select from an in-house application"
.. and yes it is.

-Steeve

---

From: Ray O'Donnell <[email-masked]>
Date: Sat, 23 Nov 2024 13:09:24 +0000

On 23/11/2024 13:06, Steeve Boulanger wrote:
> Not 100% sure what the expression "garden variety select" means lol, 
> but I'll take a guess that it means an "select from an in-house 
> application"  .. and yes it is.

Here (Ireland) we sometimes say "common-or-garden variety".... It means 
a normal, everyday variety. :-)

Ray.

>
> -Steeve
>
> On Fri, Nov 22, 2024 at 11:18 AM Adrian Klaver 
> <[email-masked]> wrote:
>
>     >  > 1) Do the 77 share some trait the other 80 don't.
>     >
>     >  > 2) Do the OS system logs reveal anything?
>     >
>     > Nothing found in syslog
>     >
>     >  > 3) What was happening in the databases just prior to the time
>     the stats
>     > reset?
>     >

-- 
Raymond O'Donnell // Galway // Ireland
[email-masked]

---

From: Steeve Boulanger <[email-masked]>
Date: Sat, 23 Nov 2024 07:16:44 -0600

> Here (Ireland) we sometimes say "common-or-garden variety".... It means a normal, everyday variety. :-)

I'm afraid that my Irish dialect is limited to "sláinte" only ;-)  In
any case, thanks for taking the time to help with this issue. I'm
still investigating, but I think that calling the "ghostbusters" is
moving up the list now lol.

On Sat, Nov 23, 2024 at 7:09 AM Ray O'Donnell <[email-masked]> wrote:
> Not 100% sure what the expression "garden variety select" means lol, but I'll take a guess that it means an "select from an in-house application"  .. and yes it is.
>
>
> Here (Ireland) we sometimes say "common-or-garden variety".... It means a normal, everyday variety. :-)
>
> Ray.
>
>
>
>
> -Steeve
>
> On Fri, Nov 22, 2024 at 11:18 AM Adrian Klaver <[email-masked]> wrote:
>>

---

From: Adrian Klaver <[email-masked]>
Date: Sat, 23 Nov 2024 08:19:04 -0800

> moving up the list now lol.

I'm guessing shutting down Netdata did not stop the resets?

You might try setting log_min_messages to info to see if that catches 
anything.

---

From: Adrian Klaver <[email-masked]>
Date: Sat, 23 Nov 2024 09:35:28 -0800

> moving up the list now lol.

One possible scenario:

log_min_messages = info
log_min_error_statement = info
log_statement = 'all'

psql -d test -U postgres -p 5432

CREATE OR REPLACE FUNCTION public.admin_func()
  RETURNS void
  LANGUAGE plpgsql
AS $function$
BEGIN
     PERFORM pg_stat_reset();
     RAISE NOTICE 'Reset statistics';
END;
$function$

  select datname, stats_reset from pg_stat_database;
    datname    |          stats_reset
--------------+-------------------------------
  NULL         | NULL
  postgres     | NULL
  template1    | NULL
  template0    | NULL
  test         | 2024-11-23 09:21:49.421552-08
  task_manager | NULL
  test_psql    | NULL
  production   | NULL
  pp_archive   | NULL
  farm_db      | NULL

select admin_func();
NOTICE:  Reset statistics
  admin_func
------------

(1 row)

select datname, stats_reset from pg_stat_database;
    datname    |          stats_reset
--------------+-------------------------------
  NULL         | NULL
  postgres     | NULL
  template1    | NULL
  template0    | NULL
  test         | 2024-11-23 09:26:30.749257-08
  task_manager | NULL
  test_psql    | NULL
  production   | NULL
  pp_archive   | NULL
  farm_db      | NULL

2024-11-23 09:26:30.749 PST [14501] postgres@test LOG:  statement: 
select admin_func();
2024-11-23 09:26:30.749 PST [14501] postgres@test NOTICE:  Reset statistics
2024-11-23 09:26:30.749 PST [14501] postgres@test CONTEXT:  PL/pgSQL 
function admin_func() line 4 at RAISE
2024-11-23 09:26:30.749 PST [14501] postgres@test STATEMENT:  select 
admin_func();

The issue being that the pg_stat_reset() is buried in a function and 
does not show up on its own. The RAISE NOTICE alerts in my logs just so 
I could find the function easily. It could be there is a function or 
functions in your setup doing something similar.

---

From: Steeve Boulanger <[email-masked]>
Date: Sat, 23 Nov 2024 18:20:28 -0600

Apologies for the late reply.

> I'm guessing shutting down Netdata did not stop the resets?

There was a hiccup yesterday, so I had to redo the test and wait until
today to see if there were any stats resets ... and NONE today!!

    reset_status    | cnt
--------------------+-----
 reset before today | 100
 no reset           |  57
 reset today        |   0

This is quite interesting, and a little unexpected... but in order to
confirm this theory, I have done the following just now:

1) Restart Netdata service
2) rename the "pg_stat_reset()" function , as you suggested in another
post  - very clever btw! :-)

Now let's wait until tomorrow to see if we have any stats reset and/or some
relevant errors in the PG logs!

Quick note: I did do a quick check in any user functions for any
"pg_stat_reset" calls , but didn't find any. With that said, we have 150+
databases in our cluster, so perhaps I missed something. I also did a grep
on the netdata directories, but nothing as well.

-Steeve

---

From: Adrian Klaver <[email-masked]>
Date: Sat, 23 Nov 2024 16:28:28 -0800

> today to see if there were any stats resets ... and NONE today!!

Getting closer.

> post  - very clever btw! :-)

Not sure who 'you' refers to, but just to be clear that was Greg Sabino 
Mullane.

> 
> Now let's wait until tomorrow to see if we have any stats reset and/or 
> some relevant errors in the PG logs!
> 
> "pg_stat_reset" calls , but didn't find any. With that said, we have 
> 150+ databases in our cluster, so perhaps I missed something. I also did 
> a grep on the netdata directories, but nothing as well.
> 
> -Steeve
> 
>