Re: Memory Leak executing small queries without closing the connection - FreeBSD

On 13.12.2015 18:17, Tom Lane wrote:
> Gerhard Wiesinger <lists(at)wiesinger(dot)com> writes:
>>> Mem: 7814M Active, 20G Inact, 2982M Wired, 232M Cache, 1661M Buf, 30M Free
>>> Swap: 512M Total, 506M Used, 6620K Free, 98% Inuse
>> OK, but why do we then get: kernel: swap_pager_getswapspace(4): failed?
> Just judging from the name of the function, I would bet this is a direct
> result of having only 512M of swap configured. As Bill already pointed
> out, that's a pretty useless choice on a system with 32G of RAM. As soon
> as the kernel tries to push out any significant amount of idle processes,
> it's gonna be out of swap space. The numbers you show above prove that
> it is almost out of free swap already.

The system wasn't designed by me, I wouldn't do it either that way. Does
swapoff help?

>
> Also, while that 20G of "inactive" pages may be candidates for reuse,
> they probably can't actually be reused without swapping them out ...
> and there's noplace for that data to go.

There is no log in syslog (where postgres log) when
swap_pager_getswapspace is logged.

But why do we have 20G of Inactive pages? They are still allocated by
kernel or user space. As you can see below (top output) NON Postgres
processes are around 9G in virtual size, resident even lower. The system
is nearly idle, and the queries typically aren't active after one second
agin. Therefore where does the rest of the 11G of Inactive pages come
from (if it isn't a Postgres/FreeBSD memory leak)?
I read that Postgres has it's own memory allocator:
https://www.reddit.com/r/programming/comments/18zija/github_got_30_better_performance_using_tcmalloc/
Might that be an issue with double allocation/freeing and the "cheese
hole" topic with memory fragmentation?

https://www.opennet.ru/base/dev/fbsdvm.txt.html
inactive pages not actively used by programs which are
dirty and (at some point) need to be written
to their backing store (typically disk).
These pages are still associated with objects and
can be reclaimed if a program references them.
Pages can be moved from the active to the inactive
queue at any time with little adverse effect.
Moving pages to the cache queue has bigger
consequences (note 1)

https://unix.stackexchange.com/questions/134862/what-do-the-different-memory-counters-in-freebsd-mean
Active: Memory currently being used by a process
Inactive: Memory that has been freed but is still cached since it
may be used again. If more Free memory is required, this memory can be
cleared and become free. This memory is not cleared before it is needed,
because "free memory is wasted memory", it doesn't cost anything to keep
the old data around in case it is needed again.
Wired: Memory in use by the Kernel. This memory cannot be swapped
out (GW: including ZFS cache!!!)
Cache: Memory being used to cache data, can be freed immediately if
required
Buffers: Disk cache
Free: Memory that is completely free and ready to use. Inactive,
Cache and Buffers can become free if they are cleaned up.

Thnx.

Ciao,
Gerhard

================================================================================================================================================================
last pid: 7277; load averages: 0.91, 0.96, 1.02 up 18+06:22:31
18:57:54
135 processes: 2 running, 132 sleeping, 1 waiting

Mem: 8020M Active, 19G Inact, 3537M Wired, 299M Cache, 1679M Buf, 38M Free
Swap: 512M Total, 501M Used, 12M Free, 97% Inuse

PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
77941 pgsql 5 20 0 7921M 7295M usem 7 404:32 10.25%
postgres
79570 pgsql 1 20 0 7367M 6968M sbwait 6 4:24 0.59% postgres
73449 pgsql 1 27 0 7367M 6908M sbwait 4 8:08 5.08% postgres
74209 pgsql 1 27 0 7367M 6803M sbwait 0 6:37 1.46% postgres
74207 pgsql 1 25 0 7367M 6748M sbwait 6 6:34 1.76% postgres
74206 pgsql 1 22 0 7367M 6548M sbwait 5 6:44 1.86% postgres
73380 pgsql 1 23 0 7367M 7265M sbwait 4 8:15 1.17% postgres
74208 pgsql 1 24 0 7367M 7223M sbwait 1 6:30 4.59% postgres
79569 pgsql 1 24 0 7367M 7105M sbwait 3 4:36 1.17% postgres
74210 pgsql 1 29 0 7363M 7182M sbwait 5 6:41 5.47% postgres
73479 pgsql 1 22 0 7363M 6560M sbwait 6 7:14 3.56% postgres
83030 pgsql 1 20 0 7329M 193M sbwait 5 0:00 0.00% postgres
76178 pgsql 1 20 0 7323M 7245M sbwait 2 3:44 0.00% postgres
75867 pgsql 1 20 0 7323M 7245M sbwait 2 3:45 0.00% postgres
75869 pgsql 1 20 0 7323M 7245M sbwait 2 3:46 0.00% postgres
75883 pgsql 1 20 0 7323M 7245M sbwait 7 3:46 0.00% postgres
76180 pgsql 1 20 0 7323M 7245M sbwait 7 3:45 0.00% postgres
75868 pgsql 1 20 0 7323M 7245M sbwait 6 3:46 0.00% postgres
76177 pgsql 1 20 0 7323M 7245M sbwait 3 3:45 0.00% postgres
76179 pgsql 1 20 0 7323M 7245M sbwait 3 3:44 0.00% postgres
75884 pgsql 1 20 0 7323M 7245M sbwait 7 3:46 0.00% postgres
76181 pgsql 1 20 0 7323M 7245M sbwait 7 3:44 0.00% postgres
75862 pgsql 1 20 0 7321M 7266M select 0 8:00 0.00% postgres
75863 pgsql 1 20 0 7321M 7261M select 4 4:04 0.00% postgres
4361 pgsql 1 20 0 7321M 206M sbwait 2 0:00 0.00%
postgres
7021 pgsql 1 20 0 7321M 181M sbwait 0 0:00 0.00%
postgres
83028 pgsql 1 20 0 7321M 180M sbwait 3 0:00 0.00% postgres
97964 pgsql 1 20 0 7321M 175M sbwait 4 0:00 0.00% postgres
97963 pgsql 1 20 0 7321M 175M sbwait 0 0:01 0.00% postgres
75865 pgsql 1 20 0 7321M 173M select 4 0:05 0.00% postgres
75864 pgsql 1 20 0 7321M 173M select 2 0:54 0.00% postgres
593 pgsql 1 21 0 7317M 173M select 4 1:50 0.00%
postgres
32387 myusername 9 20 0 980M 375M uwait 5 69:03 1.27% node
71419 myusername 9 20 0 798M 146M uwait 1 0:40 0.00% node
77938 myusername 9 20 0 795M 115M uwait 7 691:07 15.58% node
831 myusername 9 20 0 628M 30076K uwait 7 6:28 0.00% node
77937 myusername 5 20 0 618M 21352K usem 4 0:00 0.00% node
71418 myusername 5 20 0 618M 18000K usem 0 0:00 0.00% node
622 myusername 1 20 0 261M 3388K kqread 3 41:01 0.00% nginx
623 myusername 1 20 0 261M 2528K kqread 3 0:04 0.00% nginx
621 root 1 20 0 261M 2448K pause 0 0:00 0.00% nginx
604 myusername 1 20 0 235M 12144K kqread 1 1:27 0.00% uwsgi
602 myusername 1 20 0 232M 11592K kqread 0 1:11 0.00% uwsgi
600 myusername 1 20 0 231M 8736K kqread 6 0:58 0.00% uwsgi
598 myusername 1 20 0 230M 13196K kqread 0 0:17 0.00% uwsgi
608 myusername 1 20 0 227M 11204K kqread 7 0:46 0.00% uwsgi
606 myusername 1 20 0 227M 10328K kqread 1 0:59 0.00% uwsgi
610 myusername 1 20 0 227M 11656K kqread 0 1:09 0.00% uwsgi
603 myusername 1 20 0 215M 21048K kqread 4 4:35 0.00% uwsgi
599 myusername 1 20 0 215M 19756K kqread 5 0:52 0.00% uwsgi
605 myusername 1 20 0 215M 19496K kqread 4 4:01 0.00% uwsgi
597 myusername 1 20 0 215M 19284K kqread 0 3:21 0.00% uwsgi
609 myusername 1 20 0 215M 19304K kqread 1 3:10 0.00% uwsgi
601 myusername 1 20 0 215M 17208K kqread 2 4:47 0.00% uwsgi
607 myusername 1 20 0 214M 17912K kqread 5 1:44 0.00% uwsgi
595 myusername 1 20 0 213M 12224K kqread 4 0:01 0.00% uwsgi
596 myusername 1 20 0 211M 4112K kqread 6 0:00 0.00% uwsgi
532 myusername 1 20 0 100M 4036K kqread 0 0:51 0.00% uwsgi
538 myusername 1 20 0 100M 3556K kqread 1 0:51 0.00% uwsgi
92090 myusername 1 20 0 86480K 5576K select 2 0:00 0.00% sshd
84665 myusername 1 20 0 86480K 5460K select 4 0:00 0.00% sshd
84249 myusername 1 20 0 86480K 5456K select 1 0:00 0.00% sshd
72867 myusername 1 20 0 86480K 5348K select 2 0:00 0.00% sshd
75956 myusername 1 20 0 86480K 5328K select 7 0:00 0.00% sshd
92075 root 1 21 0 86480K 5220K select 7 0:00 0.00% sshd
84653 root 1 21 0 86480K 5132K select 7 0:00 0.00% sshd
84175 root 1 20 0 86480K 5124K select 7 0:00 0.00% sshd
72863 root 1 20 0 86480K 4980K select 4 0:00 0.00% sshd
75950 root 1 20 0 86480K 4952K select 5 0:00 0.00% sshd
653 root 1 20 0 61212K 1756K select 7 0:03 0.00% sshd
92133 myusername 1 20 0 47720K 2100K wait 4 0:00 0.00% su
84828 myusername 1 20 0 47720K 2068K wait 4 0:00 0.00% su
84275 myusername 1 20 0 47720K 2068K wait 3 0:00 0.00% su
83806 myusername 1 20 0 47720K 2052K wait 0 0:00 0.00% su
72875 myusername 1 20 0 47720K 1968K wait 2 0:00 0.00% su
83852 root 1 20 0 47708K 2032K wait 2 0:00 0.00% su
84923 root 1 20 0 47708K 2032K wait 7 0:00 0.00% su
6080 myusername 1 20 0 46496K 10540K select 7 11:47 0.00% tmux
75866 pgsql 1 20 0 37304K 4964K select 1 1:56 0.00% postgres
360 unbound 1 20 0 33016K 1652K select 6 0:00 0.00% unbound
68658 myusername 1 20 0 28408K 2300K ttyin 0 0:00 0.00% psql
656 root 1 20 0 24112K 2104K select 2 0:13 0.00%
sendmail
659 smmsp 1 20 0 24112K 1932K pause 1 0:00 0.00%
sendmail
92160 root 1 20 0 23572K 3560K ttyin 2 0:00 0.00% csh
84847 root 1 20 0 23572K 3540K pause 4 0:00 0.00% csh
83809 root 1 20 0 23572K 3516K pause 7 0:00 0.00% csh
84294 root 1 20 0 23572K 3424K pause 6 0:00 0.00% csh
72876 root 1 43 0 23572K 3316K ttyin 0 0:00 0.00% csh
7276 root 1 20 0 21920K 2264K CPU4 4 0:00 0.00% top
83853 pgsql 1 47 0 17068K 2404K ttyin 6 0:00 0.00% sh
84924 pgsql 1 20 0 17068K 2384K wait 5 0:00 0.00% sh
580 _ntp 1 20 -20 16740K 1056K select 2 0:00 0.00% ntpd
579 root 1 20 -20 16732K 1036K select 6 0:00 0.00% ntpd
582 _ntp 1 52 0 16732K 904K select 4 0:00 0.00% ntpd
663 root 1 20 0 16596K 1064K nanslp 5 0:06 0.00% cron
92095 myusername 1 20 0 15668K 2940K wait 7 0:00 0.00% bash
84255 myusername 1 20 0 15668K 2932K wait 6 0:00 0.00% bash
84675 myusername 1 20 0 15668K 2932K wait 3 0:00 0.00% bash
75957 myusername 1 20 0 15668K 2820K wait 6 0:00 0.00% bash
72869 myusername 1 20 0 15668K 2772K wait 6 0:00 0.00% bash
68644 myusername 1 20 0 15668K 1620K wait 2 0:00 0.00% bash
7109 myusername 1 20 0 15668K 1000K wait 3 0:00 0.00% bash
7317 myusername 1 31 0 15668K 956K ttyin 2 0:00 0.00% bash
6120 myusername 1 20 0 15668K 868K wait 4 0:00 0.00% bash
32681 myusername 1 20 0 15668K 780K ttyin 2 0:00 0.00% bash
84934 pgsql 1 52 0 14716K 2556K nanslp 3 0:02 0.00% cmdwatch
405 root 1 20 0 14504K 984K select 5 68:40 0.00%
syslogd
712 root 1 52 0 14492K 808K ttyin 1 0:00 0.00% getty
711 root 1 52 0 14492K 808K ttyin 5 0:00 0.00% getty
716 root 1 52 0 14492K 808K ttyin 2 0:00 0.00% getty
710 root 1 52 0 14492K 808K ttyin 7 0:00 0.00% getty
714 root 1 52 0 14492K 808K ttyin 5 0:00 0.00% getty
713 root 1 52 0 14492K 808K ttyin 0 0:00 0.00% getty
715 root 1 52 0 14492K 808K ttyin 3 0:00 0.00% getty
709 root 1 52 0 14492K 808K ttyin 2 0:00 0.00% getty
316 root 1 20 0 13164K 508K select 4 0:00 0.00% devd
7277 root 1 20 0 12372K 1760K piperd 1 0:00 0.00% sed
1 root 1 20 0 9472K 116K wait 4 0:00 0.00% init
12 root 18 -84 - 0K 288K WAIT 0 91:43 0.00% intr
0 root 12 -8 0 0K 192K - 0 131:24 0.00%
kernel
15 root 12 -68 - 0K 192K - 7 1:16 0.00% usb
13 root 3 -8 - 0K 48K - 1 64:25 0.00% geom
2 root 3 -16 - 0K 48K - 0 49:12 0.00% cam
9 root 2 20 - 0K 32K sdflus 7 1:43 0.00%
bufdaemon
6 root 1 -16 - 0K 16K psleep 1 149:47 0.00%
pagedaemon
5 root 1 -8 - 0K 16K m:w1 5 45:03 0.00%
g_mirror gm0
14 root 1 -16 - 0K 16K - 3 31:12 0.00%
rand_harvestq
17 root 1 16 - 0K 16K syncer 5 10:25 0.00% syncer
16 root 1 -16 - 0K 16K vlruwt 5 0:03 0.00% vnlru
4 root 1 -16 - 0K 16K idle 7 0:00 0.00%
enc_daemon0
8 root 1 155 ki31 0K 16K pgzero 7 0:00 0.00%
pagezero
3 root 1 -16 - 0K 16K waitin 7 0:00 0.00%
sctp_iterator
7 root 1 -16 - 0K 16K psleep 2 0:00 0.00%
vmdaemon
10 root 1 -16 - 0K 16K audit_ 0 0:00 0.00% audit
================================================================================================================================================================

#!/usr/bin/env bash

while [ 1 ]; do
date +%Y.%m.%d.%H.%M.%S
echo "SELECT pid,state,now()-xact_start AS time FROM pg_stat_activity
WHERE state <> 'idle' AND pg_backend_pid()<>pid ORDER BY pid" | psql
postgres
sleep 1
done

2015.12.13.19.54.34
pid | state | time
-------+--------+-----------------
76179 | active | 00:00:00.001182
(1 row)

2015.12.13.19.54.35
pid | state | time
-----+-------+------
(0 rows)

2015.12.13.19.54.36
pid | state | time
-------+--------+------------------
73479 | active | 00:00:00.115812
75868 | active | -00:00:00.000506
(2 rows)

2015.12.13.19.54.37
pid | state | time
-----+-------+------
(0 rows)

2015.12.13.19.54.38
pid | state | time
-------+--------+-----------------
74206 | active | 00:00:00.750855
(1 row)

2015.12.13.19.54.39
pid | state | time
-------+--------+-----------------
77941 | active | 00:00:00.003457
79569 | active | 00:00:00.061027
(2 rows)

2015.12.13.19.54.40
pid | state | time
-------+--------+---------------
74207 | active | 00:00:00.2614
(1 row)
================================================================================================================================================================