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

On 11/21/24 09:29, Steeve Boulanger wrote:
> Hello,
> 
> I have noticed recently that our databases (ie most but not all) have 
> their stats reset on daily basis:
> 
> select count(case when stats_reset > (now() - interval '1 day') then 1 
> else null end) db_reset_cnt, count(*) db_total_cnt from pg_stat_database;
>   db_reset_cnt | db_total_cnt
> --------------+--------------
>             77 |          157
> 
> Furthermore, the archiver stats also get reset:
> 
> select stats_reset from pg_stat_archiver;
>            stats_reset
> -------------------------------
>   2024-11-21 13:52:35.864855+00
> 
> Some facts:
> - PostgreSQL v13.16 on Linux Ubuntu 20.04
> - There's no evidence in the logs that any pg_stat_reset* functions have 
> been executed
>              name            | setting
> ----------------------------+---------
>   log_min_duration_statement | 0
>   log_statement              | all
> - we don't have any user procs with a pg_stat_reset call
> - the timestamps of the reset across databases are sometimes close to 
> each other, but not always
> Anyone has any insight on what could be doing this daily stats reset, or 
> perhaps how to find the root cause?

https://www.postgresql.org/docs/current/monitoring-stats.html#MONITORING-STATS-SETUP

"Cumulative statistics are collected in shared memory. Every PostgreSQL 
process collects statistics locally, then updates the shared data at 
appropriate intervals. When a server, including a physical replica, 
shuts down cleanly, a permanent copy of the statistics data is stored in 
the pg_stat subdirectory, so that statistics can be retained across 
server restarts. In contrast, when starting from an unclean shutdown 
(e.g., after an immediate shutdown, a server crash, starting from a base 
backup, and point-in-time recovery), all statistics counters are reset."


> 
> Regards,
> Steeve
> 

-- 
Adrian Klaver
adrian.klaver@aklaver.com

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
adrian.klaver@aklaver.com

On 11/21/24 12:57, Steeve Boulanger wrote:
> 
>  > 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()

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.

> 
> -Steeve


-- 
Adrian Klaver
adrian.klaver@aklaver.com

On 11/21/24 13:31, Steeve Boulanger wrote:
>  > 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.
> 
> 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 <adrian.klaver@aklaver.com 
> <mailto:adrian.klaver@aklaver.com>> wrote:
> 
>     On 11/21/24 12:57, Steeve Boulanger wrote:
>      >
>      >  > 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()
> 
>     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.
> 
>      >
>      > -Steeve
> 
> 
>     -- 
>     Adrian Klaver
>     adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>
> 

-- 
Adrian Klaver
adrian.klaver@aklaver.com

On 11/21/24 15:50, Steeve Boulanger wrote:
>  > 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
> 
>  > 3) What was happening in the databases just prior to the time the stats
> 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 <..>

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.

> 
> 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 <..>

The above is some garden variety select?



-- 
Adrian Klaver
adrian.klaver@aklaver.com

> 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

On Fri, Nov 22, 2024 at 11:18 AM Adrian Klaver <adrian.klaver@aklaver.com> wrote:

On 11/21/24 15:50, Steeve Boulanger wrote:
>  > 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
>
>  > 3) What was happening in the databases just prior to the time the stats
> 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 <..>

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.

>
> 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 <..>

The above is some garden variety select?



--
Adrian Klaver
adrian.klaver@aklaver.com

-- 
Raymond O'Donnell // Galway // Ireland
ray@rodonnell.ie

> 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 <ray@rodonnell.ie> wrote:
>
> On 23/11/2024 13:06, Steeve Boulanger wrote:
>
>
> > 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
froman 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 <adrian.klaver@aklaver.com> wrote:
>>
>> On 11/21/24 15:50, Steeve Boulanger wrote:
>> >  > 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
>> >
>> >  > 3) What was happening in the databases just prior to the time the stats
>> > 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 <..>
>>
>> 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.
>>
>> >
>> > 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 <..>
>>
>> The above is some garden variety select?
>>
>>
>>
>> --
>> Adrian Klaver
>> adrian.klaver@aklaver.com
>>
>
>
> --
> Raymond O'Donnell // Galway // Ireland
> ray@rodonnell.ie

On 11/23/24 05:16, Steeve Boulanger wrote:
>> 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.

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.


> 
> 
> On Sat, Nov 23, 2024 at 7:09 AM Ray O'Donnell <ray@rodonnell.ie> wrote:
>>
>> On 23/11/2024 13:06, Steeve Boulanger wrote:
>>
>>


-- 
Adrian Klaver
adrian.klaver@aklaver.com

On 11/23/24 05:16, Steeve Boulanger wrote:
>> 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.

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.

> 
> 
> On Sat, Nov 23, 2024 at 7:09 AM Ray O'Donnell <ray@rodonnell.ie> wrote:
>>
>> On 23/11/2024 13:06, Steeve Boulanger wrote:
>>
>>
>>> 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
froman 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 <adrian.klaver@aklaver.com> wrote:
>>>
>>> On 11/21/24 15:50, Steeve Boulanger wrote:
>>>>   > 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
>>>>
>>>>   > 3) What was happening in the databases just prior to the time the stats
>>>> 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 <..>
>>>
>>> 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.
>>>
>>>>
>>>> 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 <..>
>>>
>>> The above is some garden variety select?
>>>
>>>
>>>
>>> --
>>> Adrian Klaver
>>> adrian.klaver@aklaver.com
>>>
>>
>>
>> --
>> Raymond O'Donnell // Galway // Ireland
>> ray@rodonnell.ie

-- 
Adrian Klaver
adrian.klaver@aklaver.com

On 11/23/24 16:20, Steeve Boulanger wrote:
> 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

Getting closer.

> 
> 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! :-)

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!
> 
> 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
> 
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com