[pgsql-jp: 42030] Re: PostgreSQL11にてPROCEDUREを使用したPL/pgSQLでメモリ増加

Kasahara Tatsuhito kasahara.tatsuhito @ gmail.com
2019年 9月 18日 (水) 11:36:00 UTC


笠原と申します。

PostgreSQL12beta3のCentOS環境で再現しますね。ある程度ProcedureがCALLされた時点でgdbで止めて
p MemoryContextStats(TopMemoryContext) でメモリ状態をログに吐き出させたところ、以下のように
プロシージャ単位のメモリ保存場所に、CALL回数にほぼ比例したキャッシュが溜まっていました。
内容はPlanなどのCache(ただし領域だけで中身はない)に見えます。
リークっぽいとは思いますが、Procedureの中で再度Procedureが大量にCALLされてしまうと
今時点ではこうなってしまうようです。
どこまで有効かはわかりませんが・・Procedureの中で CALL Procedureではなく
SELECT Functionで呼び出すようにすれば、処理内容次第ですがメモリの使い過ぎは
避けられるかもしれません。
# 手元の簡単な再現では大丈夫でした

TopMemoryContext: 80776 total in 6 blocks; 6976 free (10 chunks); 73800 used
  TopTransactionContext: 8192 total in 1 blocks; 7504 free (1 chunks); 688 used
    ExecutorState: 8192 total in 1 blocks; 3344 free (2 chunks); 4848 used
      ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
  PLpgSQL cast info: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
    PLpgSQL cast cache: 8192 total in 1 blocks; 1584 free (0 chunks); 6608 used
  PL/pgSQL function: 8192 total in 1 blocks; 4968 free (3 chunks);
3224 used: p_dps11z()
  PL/pgSQL function: 92274688 total in 21 blocks; 3342320 free (17
chunks); 88932368 used: pc_dps11e(integer) ★
  CFuncHash: 8192 total in 1 blocks; 560 free (0 chunks); 7632 used
  Rendezvous variable hash: 8192 total in 1 blocks; 560 free (0
chunks); 7632 used
  PLpgSQL function hash: 24528 total in 2 blocks; 2624 free (0
chunks); 21904 used
  RowDescriptionContext: 8192 total in 1 blocks; 6896 free (0 chunks); 1296 used
  MessageContext: 8192 total in 1 blocks; 3864 free (1 chunks); 4328 used
  Operator class cache: 8192 total in 1 blocks; 560 free (0 chunks); 7632 used
  smgr relation table: 32768 total in 3 blocks; 16832 free (8 chunks);
15936 used
  TransactionAbortContext: 32768 total in 1 blocks; 32512 free (0
chunks); 256 used
  Portal hash: 8192 total in 1 blocks; 560 free (0 chunks); 7632 used
  TopPortalContext: 8192 total in 1 blocks; 7664 free (0 chunks); 528 used
    PortalContext: 1024 total in 1 blocks; 392 free (0 chunks); 632 used:
      SPI Proc: 131072 total in 5 blocks; 10000 free (0 chunks); 121072 used
        CachedPlan: 1024 total in 1 blocks; 80 free (0 chunks); 944
used: CALL p_dps11z()
        CachedPlanSource: 1024 total in 1 blocks; 144 free (0 chunks);
880 used: CALL p_dps11z()
          CachedPlanQuery: 2048 total in 2 blocks; 936 free (1
chunks); 1112 used
        (繰り返し・・)
        SPI Plan: 1024 total in 1 blocks; 608 free (0 chunks); 416 used
        CachedPlan: 1024 total in 1 blocks; 80 free (0 chunks); 944
used: CALL p_dps11z()
        14902 more child contexts containing 25446400 total in 24836
blocks; 8796248 free (4967 chunks); 16650152 used ★
      ExecutorState: 8192 total in 1 blocks; 5920 free (0 chunks); 2272 used
        ExprContext: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
  Relcache by OID: 16384 total in 2 blocks; 3512 free (2 chunks); 12872 used
  CacheMemoryContext: 1048576 total in 8 blocks; 477824 free (3
chunks); 570752 used
    CachedPlan: 2048 total in 2 blocks; 392 free (0 chunks); 1656
used: SELECT pg_sleep(10.0)
    CachedPlanSource: 2048 total in 2 blocks; 304 free (0 chunks);
1744 used: SELECT pg_sleep(10.0)
  (略)
  WAL record construction: 49768 total in 2 blocks; 6368 free (0
chunks); 43400 used
  PrivateRefCount: 8192 total in 1 blocks; 2624 free (0 chunks); 5568 used
  MdSmgr: 8192 total in 1 blocks; 6952 free (0 chunks); 1240 used
  LOCALLOCK hash: 8192 total in 1 blocks; 560 free (0 chunks); 7632 used
  Timezones: 104120 total in 2 blocks; 2624 free (0 chunks); 101496 used
  ErrorContext: 8192 total in 1 blocks; 7936 free (5 chunks); 256 used
Grand total: 119764088 bytes in 25245 blocks; 12907720 free (5135
chunks); 106856368 used

2019年9月13日(金) 10:11 TAKATSUKA Haruka <harukat @ postgresql.jp>:
>
> 永吉さん、
> 高塚と申します。
>
> Linux で調べると、ループが続く限りプロセスの使用メモリが増え続ける
> というわけでも無いですね。
> ただ、一時的にプロセスの使用メモリ量が大きく膨らむ動作は観測できました。
> あまり詳しく調べていないのですが、ひとまず報告しておきます。
>
> db1=# CREATE TABLE t1 (id int, v text);
> db1=# INSERT INTO t1 SELECT g, md5(g::text) FROM generate_series(1, 100000) g;
> db1=# CREATE PROCEDURE pc_sub() LANGUAGE plpgsql AS $$ DECLARE rec RECORD;
>       BEGIN SELECT * INTO rec FROM t1; NULL; END; $$;
> db1=# CREATE PROCEDURE pc_main(c int) LANGUAGE plpgsql AS $$ DECLARE n int;
>       BEGIN FOR n IN 1 .. c LOOP CALL pc_sub(); END LOOP; END $$;
> db1=# CALL pc_main(1000000);
>
> [postgres ~]$ ps x | grep CALL | grep -v grep
> 16867 ?        Ds     1:22 postgres: postgres db1 [local] CALL
> [postgres ~]$ p=16867 ; echo -n "PID:$p mem use(kB):" ; \
>   cat /proc/$p/smaps | grep Private | sed -e 's/^.*://' -e 's/kB//' | \
>   awk '{ sum += $1 } ; END { print sum }'
> PID:16867 mem use(kB):220980
> [postgres ~]$ p=16867 ; echo -n "PID:$p mem use(kB):" ; \
>   cat /proc/$p/smaps | grep Private | sed -e 's/^.*://' -e 's/kB//' | \
>   awk '{ sum += $1 } ; END { print sum }'
> PID:16867 mem use(kB):339668
>
> (以下結果だけ)
> PID:16867 mem use(kB):453888
> PID:16867 mem use(kB):638172
> PID:16867 mem use(kB):880916
> PID:16867 mem use(kB):1036772
> PID:16867 mem use(kB):1289756
> PID:16867 mem use(kB):1457176
> PID:16867 mem use(kB):1647164
> PID:16867 mem use(kB):2012496
> PID:16867 mem use(kB):2639904
> PID:16867 mem use(kB):3170596
> PID:16867 mem use(kB):3504604
> PID:16867 mem use(kB):3497824
> PID:16867 mem use(kB):3517192
> PID:16867 mem use(kB):3491892
> PID:16867 mem use(kB):3509284
> PID:16867 mem use(kB):1141636
> PID:16867 mem use(kB):908084
> PID:16867 mem use(kB):852668
> PID:16867 mem use(kB):73376
> PID:16867 mem use(kB):73372
> PID:16867 mem use(kB):73376
> PID:16867 mem use(kB):73372
> PID:16867 mem use(kB):73372
>
>
> On Wed, 11 Sep 2019 19:10:29 +0900 (JST)
> "misakana @ yahoo.co.jp" <misakana @ yahoo.co.jp> wrote:
>
> > 初めて投稿いたします。永吉と申します。
> >
> > PostgreSQL11でPROCEDUREを使用したPL/pgSQLにてツールを作成しています。
> > (Ver.11からのトランザクション機能を活用するためPROCEDUREを使用)
> >
> > テーブル項目の更新を確認するPROCEDUREを作成し、親となるPROCEDUREから
> > そのPROCEDUREを繰り返し呼び出す(CALLする)構造にしています。この時、
> > Windows側で該当するプロセスのメモリ使用量が増加し、総メモリ使用量が
> > 100%近くなった段階で、PROCEDUREが「ERROR: out of memory」となり停止
> > してしまいます。
> >
> > <環境>
> >   -Windows 7 Professional Service Pack1 64Bit
> >   -実装メモリ 4GB
> >   -PostgreSQL 11.5, compiled by Visual C++ build 1914, 64-bit
> >
> > <ソース> <= 実際は複雑ですが下記だけで再現します。
> >
> > CREATE OR REPLACE PROCEDURE pc_dps11e(re_count integer)
> > LANGUAGE 'plpgsql' AS $BODY$
> > DECLARE
> >     n integer;  -- ループ変数
> > BEGIN
> >     RAISE NOTICE '## ひたすらプロシジャを呼び出す ##';
> >     RAISE NOTICE 'START : %', TO_CHAR(clock_timestamp(), 'YYYY/MM/DD HH24:MI:SS');
> >
> >     FOR n IN 1..re_count LOOP
> >         CALL p_dps11z();
> >     END LOOP;
> >     RAISE NOTICE 'END  : %', TO_CHAR(clock_timestamp(), 'YYYY/MM/DD HH24:MI:SS');
> >     PERFORM pg_sleep(10.0);
> > END; $BODY$;
> >
> > CREATE OR REPLACE PROCEDURE p_dps11z()
> > LANGUAGE 'plpgsql' AS $BODY$
> > BEGIN
> > -- SELECT * TO REC FROM ...
> >     NULL;
> > END; $BODY$;
> >
> > CALL pc_dps11e(500000);
> >
> > PostgreSQL11自体のメモリリークを疑っているのですが、
> > ご教授いただけたら幸いです。よろしくお願いします。
> >
>
>
> ______________________________________________________________________
>  日本PostgreSQLユーザ会  高塚 遥
>  〒171-0022 東京都豊島区南池袋2-32-8 SRA OSS 日本支社 内 JPUG
>  Mail: harukat @ postgresql.jp  TEL: 03-5979-2729



-- 
Tatsuhito Kasahara
kasahara.tatsuhito _at_ gmail.com


pgsql-jp メーリングリストの案内