Thread: often PREPARE can generate high load (and sometimes minutes long unavailability)

often PREPARE can generate high load (and sometimes minutes long unavailability)

From

Pavel Stehule

Date:

23 February 2014, 22:05:23

Hello

I got a example of code, that generate relatively high load with minimal connections.

This code is +/- bad - it repeatedly generate prepare statement, but somewhere uses prepared statements as protections against SQL injections and they can use same use case.

Pseudocode (I can send a test case privately):

Script a:

-- A,B are in RAM

for i in 1 .. N loop

insert into A values();

for j in 1 .. M loop

insert into B values();

end loop;

Script b:

-- query is extremely fast - returns 0 or 1 rows usually

40 threads execute

while true loop

pr = PREPARE SELECT * FROM A LEFT JOIN B ON ..

EXECUTE pr(...)

sleep(10 ms)

end loop

running both script together can produce high load with minimal number of executed queries.

354246.00 93.0% s_lock /usr/lib/postgresql/9.2/bin/postgres

10503.00 2.8% LWLockRelease /usr/lib/postgresql/9.2/bin/postgres

8802.00 2.3% LWLockAcquire /usr/lib/postgresql/9.2/bin/postgres

828.00 0.2% _raw_spin_lock [kernel.kallsyms]

559.00 0.1% _raw_spin_lock_irqsave [kernel.kallsyms]

340.00 0.1% switch_mm [kernel.kallsyms]

305.00 0.1% poll_schedule_timeout [kernel.kallsyms]

274.00 0.1% native_write_msr_safe [kernel.kallsyms]

257.00 0.1% _raw_spin_lock_irq [kernel.kallsyms]

238.00 0.1% apic_timer_interrupt [kernel.kallsyms]

236.00 0.1% __schedule [kernel.kallsyms]

213.00 0.1% HeapTupleSatisfiesMVCC

With systemtap I got list of spin locks

light weight locks
            lockname       mode      count        avg (time)
        DynamicLocks Exclusive       2804       1025
        DynamicLocks     Shared        106        130
       ProcArrayLock Exclusive         63     963551
       ProcArrayLock     Shared         50       4160
        LockMgrLocks Exclusive         18        159
     IndividualLock   Exclusive          2          7

There is relative few very long ProcArrayLocks lwlocks

This issue is very pathologic on fast computers with more than 8 CPU. This issue was detected after migration from 8.4 to 9.2. (but tested with same result on 9.0) I see it on devel 9.4 today actualized.

When I moved PREPARE from cycle, then described issues is gone. But when I use a EXECUTE IMMEDIATELY, then the issue is back. So it looks it is related to planner, ...

Regards

Pavel

Re: often PREPARE can generate high load (and sometimes minutes long unavailability)

From

Jeff Janes

Date:

23 February 2014, 22:35:31

On Sun, Feb 23, 2014 at 11:04 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote:

Hello

I got a example of code, that generate relatively high load with minimal connections.

This code is +/- bad - it repeatedly generate prepare statement, but somewhere uses prepared statements as protections against SQL injections and they can use same use case.

Pseudocode (I can send a test case privately):

Script a:

-- A,B are in RAM
for i in 1 .. N loop
    insert into A values();
    for j in 1 .. M loop
      insert into B values();
    end loop;
end loop;

Script b:

-- query is extremely fast - returns 0 or 1 rows usually
40 threads execute
while true loop
pr = PREPARE SELECT * FROM A LEFT JOIN B ON ..
EXECUTE pr(...)
sleep(10 ms)
end loop

Digging through uncommitted tuples at the top or bottom of an index (which happenings during planning, especially the planner of merge joins) is very contentious. Tom proposed changing the snapshot used for planning to Dirty, but the proposal didn't go anywhere because no one did the testing to confirm that it solved the problem in the field. Perhaps you can help do that.

See:

"[PERFORM] Performance bug in prepared statement binding in 9.2?" and several related threads.

Cheers,

Jeff

Re: often PREPARE can generate high load (and sometimes minutes long unavailability)

From

Pavel Stehule

Date:

23 February 2014, 23:05:24

2014-02-23 20:35 GMT+01:00 Jeff Janes <jeff.janes@gmail.com>:

On Sun, Feb 23, 2014 at 11:04 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote:
Hello

I got a example of code, that generate relatively high load with minimal connections.

This code is +/- bad - it repeatedly generate prepare statement, but somewhere uses prepared statements as protections against SQL injections and they can use same use case.

Pseudocode (I can send a test case privately):

Script a:

-- A,B are in RAM
for i in 1 .. N loop
    insert into A values();
    for j in 1 .. M loop
      insert into B values();
    end loop;
end loop;

Script b:

-- query is extremely fast - returns 0 or 1 rows usually
40 threads execute
while true loop
pr = PREPARE SELECT * FROM A LEFT JOIN B ON ..
EXECUTE pr(...)
sleep(10 ms)
end loop

Digging through uncommitted tuples at the top or bottom of an index (which happenings during planning, especially the planner of merge joins) is very contentious. Tom proposed changing the snapshot used for planning to Dirty, but the proposal didn't go anywhere because no one did the testing to confirm that it solved the problem in the field. Perhaps you can help do that.

I am able to test some patches. Thank you for info

Regards

Pavel

See:

"[PERFORM] Performance bug in prepared statement binding in 9.2?" and several related threads.

Cheers,

Jeff

Re: often PREPARE can generate high load (and sometimes minutes long unavailability)

From

Pavel Stehule

Date:

23 February 2014, 23:17:37

2014-02-23 20:35 GMT+01:00 Jeff Janes <jeff.janes@gmail.com>:

On Sun, Feb 23, 2014 at 11:04 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote:
Hello

I got a example of code, that generate relatively high load with minimal connections.

This code is +/- bad - it repeatedly generate prepare statement, but somewhere uses prepared statements as protections against SQL injections and they can use same use case.

Pseudocode (I can send a test case privately):

Script a:

-- A,B are in RAM
for i in 1 .. N loop
    insert into A values();
    for j in 1 .. M loop
      insert into B values();
    end loop;
end loop;

Script b:

-- query is extremely fast - returns 0 or 1 rows usually
40 threads execute
while true loop
pr = PREPARE SELECT * FROM A LEFT JOIN B ON ..
EXECUTE pr(...)
sleep(10 ms)
end loop

Digging through uncommitted tuples at the top or bottom of an index (which happenings during planning, especially the planner of merge joins) is very contentious. Tom proposed changing the snapshot used for planning to Dirty, but the proposal didn't go anywhere because no one did the testing to confirm that it solved the problem in the field. Perhaps you can help do that.

See:

"[PERFORM] Performance bug in prepared statement binding in 9.2?" and several related threads.

yes, it is very similar. Only it is little bit worse - on 16CPU it can produce a 20-60 minutes unavailability

regards

Pavel

Cheers,

Jeff

Re: often PREPARE can generate high load (and sometimes minutes long unavailability)

From

Andres Freund

Date:

23 February 2014, 23:32:13

Hi,

On 2014-02-23 20:04:39 +0100, Pavel Stehule wrote:
> There is relative few very long ProcArrayLocks lwlocks
> 
> This issue is very pathologic on fast computers with more than 8 CPU. This
> issue was detected after migration from 8.4 to 9.2. (but tested with same
> result on 9.0)  I see it on devel 9.4 today actualized.
> 
> When I moved PREPARE from cycle, then described issues is gone. But when I
> use a EXECUTE IMMEDIATELY, then the issue is back. So it looks it is
> related to planner, ...

In addition to the issue Jeff mentioned, I'd suggest trying the same
workload with repeatable read. That can do *wonders* because of the
reduced number of snapshots.

Greetings,

Andres Freund

-- Andres Freund                       http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services

Re: often PREPARE can generate high load (and sometimes minutes long unavailability)

From

Pavel Stehule

Date:

24 February 2014, 18:03:19

2014-02-23 21:32 GMT+01:00 Andres Freund <andres@2ndquadrant.com>:

Hi,

On 2014-02-23 20:04:39 +0100, Pavel Stehule wrote:
> There is relative few very long ProcArrayLocks lwlocks
>
> This issue is very pathologic on fast computers with more than 8 CPU. This
> issue was detected after migration from 8.4 to 9.2. (but tested with same
> result on 9.0) I see it on devel 9.4 today actualized.
>
> When I moved PREPARE from cycle, then described issues is gone. But when I
> use a EXECUTE IMMEDIATELY, then the issue is back. So it looks it is
> related to planner, ...

In addition to the issue Jeff mentioned, I'd suggest trying the same
workload with repeatable read. That can do *wonders* because of the
reduced number of snapshots.

I tested it, and it doesn't help.

Is there some patch, that I can test related to this issue?

Greetings,

Andres Freund

--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

Re: often PREPARE can generate high load (and sometimes minutes long unavailability)

From

Andres Freund

Date:

24 February 2014, 18:09:18

On 2014-02-23 20:04:39 +0100, Pavel Stehule wrote:
>            354246.00 93.0% s_lock
> /usr/lib/postgresql/9.2/bin/postgres
>             10503.00  2.8% LWLockRelease
>  /usr/lib/postgresql/9.2/bin/postgres
>              8802.00  2.3% LWLockAcquire
>  /usr/lib/postgresql/9.2/bin/postgres
>               828.00  0.2% _raw_spin_lock
> [kernel.kallsyms]
>               559.00  0.1% _raw_spin_lock_irqsave
> [kernel.kallsyms]
>               340.00  0.1% switch_mm
>  [kernel.kallsyms]
>               305.00  0.1% poll_schedule_timeout
>  [kernel.kallsyms]
>               274.00  0.1% native_write_msr_safe
>  [kernel.kallsyms]
>               257.00  0.1% _raw_spin_lock_irq
> [kernel.kallsyms]
>               238.00  0.1% apic_timer_interrupt
> [kernel.kallsyms]
>               236.00  0.1% __schedule
> [kernel.kallsyms]
>               213.00  0.1% HeapTupleSatisfiesMVCC
> 
> With systemtap I got list of spin locks
> 
> light weight locks
>             lockname       mode      count        avg (time)
>         DynamicLocks  Exclusive       2804       1025
>         DynamicLocks     Shared        106        130
>        ProcArrayLock  Exclusive         63     963551
>        ProcArrayLock     Shared         50       4160
>         LockMgrLocks  Exclusive         18        159
>      IndividualLock   Exclusive          2          7
> 
> There is relative few very long ProcArrayLocks lwlocks

It's odd that there are so many exclusive acquisition
ProcArrayLocks... A hierarchical profile would be interesting. I'd
suggest compiling postgres with -fno-omit-frame-pointer and doing a
profile with perf.

Greetings,

Andres Freund

-- Andres Freund                       http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services

Re: often PREPARE can generate high load (and sometimes minutes long unavailability)

From

Pavel Stehule

Date:

24 February 2014, 21:04:35

2014-02-24 16:09 GMT+01:00 Andres Freund <andres@2ndquadrant.com>:

On 2014-02-23 20:04:39 +0100, Pavel Stehule wrote:
> 354246.00 93.0% s_lock
> /usr/lib/postgresql/9.2/bin/postgres
> 10503.00 2.8% LWLockRelease
> /usr/lib/postgresql/9.2/bin/postgres
> 8802.00 2.3% LWLockAcquire
> /usr/lib/postgresql/9.2/bin/postgres
> 828.00 0.2% _raw_spin_lock
> [kernel.kallsyms]
> 559.00 0.1% _raw_spin_lock_irqsave
> [kernel.kallsyms]
> 340.00 0.1% switch_mm
> [kernel.kallsyms]
> 305.00 0.1% poll_schedule_timeout
> [kernel.kallsyms]
> 274.00 0.1% native_write_msr_safe
> [kernel.kallsyms]
> 257.00 0.1% _raw_spin_lock_irq
> [kernel.kallsyms]
> 238.00 0.1% apic_timer_interrupt
> [kernel.kallsyms]
> 236.00 0.1% __schedule
> [kernel.kallsyms]
> 213.00 0.1% HeapTupleSatisfiesMVCC
>
> With systemtap I got list of spin locks
>
> light weight locks
> lockname mode count avg (time)
> DynamicLocks Exclusive 2804 1025
> DynamicLocks Shared 106 130
> ProcArrayLock Exclusive 63 963551
> ProcArrayLock Shared 50 4160
> LockMgrLocks Exclusive 18 159
> IndividualLock Exclusive 2 7
>
> There is relative few very long ProcArrayLocks lwlocks

It's odd that there are so many exclusive acquisition
ProcArrayLocks... A hierarchical profile would be interesting. I'd
suggest compiling postgres with -fno-omit-frame-pointer and doing a
profile with perf.

I had no experience with perf, so maybe it is not what you want

- 19.59%       postmaster postgres
   - s_lock
      - 55.06% LWLockAcquire
         + 99.84% TransactionIdIsInProgress
      - 44.63% LWLockRelease
         + 99.91% TransactionIdIsInProgress
- 13.84%       postmaster postgres
   - tas
      - 97.97% s_lock
         + 55.01% LWLockAcquire
         + 44.99% LWLockRelease
      - 1.10% LWLockAcquire
         + 99.89% TransactionIdIsInProgress
      - 0.93% LWLockRelease
         + 99.93% TransactionIdIsInProgress

- 19.59%       postmaster postgres
   - s_lock
      - 55.06% LWLockAcquire
         - 99.84% TransactionIdIsInProgress
              HeapTupleSatisfiesMVCC
              heap_hot_search_buffer
              index_fetch_heap
              index_getnext
              get_actual_variable_range
              ineq_histogram_selectivity
              scalarineqsel
              mergejoinscansel
              cached_scansel
              initial_cost_mergejoin
              try_mergejoin_path
              sort_inner_and_outer
              add_paths_to_joinrel
              make_join_rel
              make_rels_by_clause_joins
              join_search_one_level
              standard_join_search
              make_rel_from_joinlist
              make_one_rel
              query_planner
              grouping_planner
              subquery_planner
              standard_planner
              planner
              pg_plan_query
              pg_plan_queries
              BuildCachedPlan
              GetCachedPlan
              exec_bind_message
              PostgresMain
              ExitPostmaster
              BackendStartup
              ServerLoop
              PostmasterMain
              startup_hacks

regards

Pavel

Greetings,

Andres Freund

--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

Re: often PREPARE can generate high load (and sometimes minutes long unavailability)

From

Jeff Janes

Date:

24 February 2014, 23:32:03

On Mon, Feb 24, 2014 at 7:02 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote:

2014-02-23 21:32 GMT+01:00 Andres Freund <andres@2ndquadrant.com>:

Hi,

On 2014-02-23 20:04:39 +0100, Pavel Stehule wrote:
> There is relative few very long ProcArrayLocks lwlocks
>
> This issue is very pathologic on fast computers with more than 8 CPU. This
> issue was detected after migration from 8.4 to 9.2. (but tested with same
> result on 9.0) I see it on devel 9.4 today actualized.
>
> When I moved PREPARE from cycle, then described issues is gone. But when I
> use a EXECUTE IMMEDIATELY, then the issue is back. So it looks it is
> related to planner, ...

In addition to the issue Jeff mentioned, I'd suggest trying the same
workload with repeatable read. That can do *wonders* because of the
reduced number of snapshots.

I tested it, and it doesn't help.

Is there some patch, that I can test related to this issue?

This is the one that I was referring to:

http://www.postgresql.org/message-id/11927.1384199294@sss.pgh.pa.us

Cheers,

Jeff

Re: often PREPARE can generate high load (and sometimes minutes long unavailability)

From

Pavel Stehule

Date:

25 February 2014, 13:30:42

Hello

2014-02-24 21:31 GMT+01:00 Jeff Janes <jeff.janes@gmail.com>:

On Mon, Feb 24, 2014 at 7:02 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote:

2014-02-23 21:32 GMT+01:00 Andres Freund <andres@2ndquadrant.com>:

Hi,

On 2014-02-23 20:04:39 +0100, Pavel Stehule wrote:
> There is relative few very long ProcArrayLocks lwlocks
>
> This issue is very pathologic on fast computers with more than 8 CPU. This
> issue was detected after migration from 8.4 to 9.2. (but tested with same
> result on 9.0) I see it on devel 9.4 today actualized.
>
> When I moved PREPARE from cycle, then described issues is gone. But when I
> use a EXECUTE IMMEDIATELY, then the issue is back. So it looks it is
> related to planner, ...

In addition to the issue Jeff mentioned, I'd suggest trying the same
workload with repeatable read. That can do *wonders* because of the
reduced number of snapshots.

I tested it, and it doesn't help.

Is there some patch, that I can test related to this issue?

This is the one that I was referring to:

http://www.postgresql.org/message-id/11927.1384199294@sss.pgh.pa.us

I tested this patch with great success. Waiting on ProcArrayLocks are off. Throughput is expected.

For described use case it is seriously interesting.

Regards

Pavel

light weight locks
            lockname       mode      count        avg
        DynamicLocks Exclusive       8055       5003
        DynamicLocks     Shared       1666         50
        LockMgrLocks Exclusive        129         36
     IndividualLock   Exclusive         34         48
     IndividualLock      Shared         21          7
     BufFreelistLock Exclusive         12          8
        WALWriteLock Exclusive          1      38194
       ProcArrayLock     Shared          1          8

Cheers,

Jeff

Re: often PREPARE can generate high load (and sometimes minutes long unavailability)

From

Pavel Stehule

Date:

25 February 2014, 17:52:27

2014-02-25 11:29 GMT+01:00 Pavel Stehule <pavel.stehule@gmail.com>:

Hello

2014-02-24 21:31 GMT+01:00 Jeff Janes <jeff.janes@gmail.com>:

On Mon, Feb 24, 2014 at 7:02 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote:

2014-02-23 21:32 GMT+01:00 Andres Freund <andres@2ndquadrant.com>:

Hi,

On 2014-02-23 20:04:39 +0100, Pavel Stehule wrote:
> There is relative few very long ProcArrayLocks lwlocks
>
> This issue is very pathologic on fast computers with more than 8 CPU. This
> issue was detected after migration from 8.4 to 9.2. (but tested with same
> result on 9.0) I see it on devel 9.4 today actualized.
>
> When I moved PREPARE from cycle, then described issues is gone. But when I
> use a EXECUTE IMMEDIATELY, then the issue is back. So it looks it is
> related to planner, ...

In addition to the issue Jeff mentioned, I'd suggest trying the same
workload with repeatable read. That can do *wonders* because of the
reduced number of snapshots.

I tested it, and it doesn't help.

Is there some patch, that I can test related to this issue?

This is the one that I was referring to:

http://www.postgresql.org/message-id/11927.1384199294@sss.pgh.pa.us

I tested this patch with great success. Waiting on ProcArrayLocks are off. Throughput is expected.

For described use case it is seriously interesting.

Here is a update for 9.4

Regards

Pavel

Regards

Pavel

light weight locks
            lockname       mode      count        avg
        DynamicLocks Exclusive       8055       5003
        DynamicLocks     Shared       1666         50
        LockMgrLocks Exclusive        129         36
     IndividualLock   Exclusive         34         48
     IndividualLock      Shared         21          7
     BufFreelistLock Exclusive         12          8
        WALWriteLock Exclusive          1      38194
       ProcArrayLock     Shared          1          8

Cheers,

Jeff

Attachment

sel_func.patch