View Issue Details

IDProjectCategoryView StatusLast Update
0000436Pgpool-IIEnhancementpublic2018-11-20 11:40
Reporterhanyugang01Assigned Topengbo 
PriorityhighSeveritymajorReproducibilityalways
Status feedbackResolutionopen 
Product Version3.7.5 
Target VersionFixed in Version 
Summary0000436: when a long session with a massive of db operation, the child pgpool process consume too much cpu resource
DescriptionOS:
CentOS Linux release 7.4.1708 (Core)
Kernel:
Linux bogon 3.10.0-693.17.1.el7.x86_64 0000001 SMP Thu Jan 25 20:13:58 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
Pgpool:
3.7.5 installed by yum repo

I had setup a very simple pgpool(3.7.5)+postgresql(10.5) environment, which has no watchdog and load balance feature and just one backend postgresql instance.
And also I have a damon program(writen by golang),and the program load a massive dataset to postgresql.Here is the situation I met:
1. When I connect the postgresql server directly, I can see the total cpu uasge is about 20%(of cource, the most heavist cpu load hold by postgres process)
2. When I connect the pgpool directly, I can see the cpu usage is about 100%(the most heavist cpu load hold by pgpool child process, about 70%)
And I use the strace tool to inspect what happend, below is the result:
strace: Process 1646 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
 78.30 0.020824 1 28577 write
 14.55 0.003870 0 11432 select
  5.34 0.001419 0 7621 read
  1.64 0.000436 0 3810 rt_sigprocmask
  0.18 0.000047 0 120 brk
------ ----------- ----------- --------- --------- ----------------
100.00 0.026596 51560 total
And the stack is:
[root@localhost ~]# pstack 2259
#0 0x00007fd0e74683a3 in ?? ()
0000001 0x0000563728f69277 in read_packets_and_process (frontend=frontend@entry=0x56372adacb98, backend=backend@entry=0x56372ad7f8b8, reset_request=reset_request@entry=0, state=state@entry=0x7fff6014f9b4, num_fields=num_fields@entry=0x7fff6014f9b2, cont=cont@entry=0x7fff6014f9bc "\001") at protocol/pool_process_query.c:4594
0000002 0x0000563728f6a434 in pool_process_query (frontend=0x56372adacb98, backend=0x56372ad7f8b8, reset_request=reset_request@entry=0) at protocol/pool_process_query.c:273
0000003 0x0000563728f64839 in do_child (fds=fds@entry=0x56372ad70b90) at protocol/child.c:384
0000004 0x0000563728f45c07 in fork_a_child (fds=0x56372ad70b90, id=214) at main/pgpool_main.c:611
0000005 0x0000563728f46d0e in reaper () at main/pgpool_main.c:2545
0000006 0x0000563728f4c018 in PgpoolMain (discard_status=discard_status@entry=1 '\001', clear_memcache_oidmaps=clear_memcache_oidmaps@entry=0 '\000') at main/pgpool_main.c:440
0000007 0x0000563728f441d1 in main (argc=<optimized out>, argv=0x7fff6015aeb8) at main/main.c:318

Is there some way to optimize?
THANKS VERY MUCH!!!
Steps To ReproduceA program using a single connection to pgpool, do a massive operation to the database, we can see that the child pgpool process consume too much cpu resource.
Additional InformationI submit the pgpool conf file(pgpool.conf) and the test golang program(cluster.go).
TagsNo tags attached.

Activities

hanyugang01

2018-10-15 15:38

reporter  

cluster.go (2,915 bytes)
pgpool.conf (35,559 bytes)

hanyugang01

2018-10-15 19:43

reporter   ~0002199

we found that when massive insert operations situation met, the problem reproduce instantly.

hanyugang01

2018-10-17 10:58

reporter   ~0002205

after reviewing code of our test program , we found the problem is that:we should not create too many stmt objects, the usage of stmt is not correct.
bad case:
for i := 0; i < testCount; i++ {
        ...
        stmt, err := db.Prepare(sqlStatement)
        if err != nil {
            fmt.Println("prepare sql failed, err->", err, "sql->", sqlStatement)
            continue
        }
        res, err := stmt.Exec()
        if err != nil {
            fmt.Println("insert into test failed, err->", err, "res->", res, "sql->", sqlStatement)
            continue
        }
}

good case:
sqlStatement := fmt.Sprintf(`INSERT INTO test(
            name,
            id,
            age) VALUES($1,$2,$3)`)
stmt, err := db.Prepare(sqlStatement)
if err != nil {
    fmt.Println("prepare sql failed, err->", err, "sql->", sqlStatement)
    continue
}
for i := 0; i < testCount; i++ {
        res, err := stmt.Exec(param1, param2, param3)
        if err != nil {
            fmt.Println("insert into test failed, err->", err, "res->", res, "sql->", sqlStatement)
            continue
        }
}

after we revise our code, we found that the cpu load of pgpool is ok.

BUT, the problem is still exist, which is that when we create many stmt objects, pgpool child process consume high cpu resource.By the way, when we directly connect postgresql server, even we create many stmt objects, the cpu load is not high.
we also using flamegrapgh tools to inspect what happend.

pgpool_cpu_not_high.svg (123,693 bytes)
pgpool_cpu_high.svg (165,026 bytes)

pengbo

2018-10-22 09:51

developer   ~0002224

I will confirm that this issue is from Pgpool-II or application?

t-ishii

2018-10-24 20:01

developer   ~0002230

If the application never removes prepared statements in a session, it's not surprising that Pgpool-II consumes much memory because it cannot free memory allocated by the prepared statements until they are removed. Also if there is tons of data to keep track each prepared statement in Pgpool-II, it's not also surprising that Pgpool-II consumes cpu because the search space for prepared statements is huge.

In summary I think you need to fix your application program so that it removes prepared statements that are no longer necessary.

Issue History

Date Modified Username Field Change
2018-10-15 15:38 hanyugang01 New Issue
2018-10-15 15:38 hanyugang01 File Added: pgpool.conf
2018-10-15 15:38 hanyugang01 File Added: cluster.go
2018-10-15 19:43 hanyugang01 Note Added: 0002199
2018-10-17 10:58 hanyugang01 File Added: pgpool_cpu_high.svg
2018-10-17 10:58 hanyugang01 File Added: pgpool_cpu_not_high.svg
2018-10-17 10:58 hanyugang01 Note Added: 0002205
2018-10-22 09:51 pengbo Note Added: 0002224
2018-10-24 20:01 t-ishii Note Added: 0002230
2018-11-20 11:40 pengbo Assigned To => pengbo
2018-11-20 11:40 pengbo Status new => feedback
2018-11-20 11:40 pengbo Description Updated View Revisions