Обсуждение: waiting for client write

Поиск

Список

Период

Сортировка

waiting for client write

От

Ayub Khan

Дата:

09 июня 2021 г., 17:47:02

attached is the screenshot of RDS performance insights for AWS and it shows high waiting client writes. The api performance is slow. I read that this might be due to IOPS on RDS. However we have 80k IOPS on this test RDS.

Below is the query which is being load tested

SELECT

a.menu_item_id,
a.menu_item_name,
a.menu_item_category_id,
b.menu_item_category_desc,
c.menu_item_variant_id,
c.menu_item_variant_type_id,
c.price,
c.size_id,
c.parent_menu_item_variant_id,
d.menu_item_variant_type_desc,
e.size_desc,
f.currency_code,
a.image,
a.mark_id,
m.mark_name

FROM .menu_item_category AS b, .menu_item_variant AS c,
.menu_item_variant_type AS d, .item_size AS e, .restaurant AS f,
.menu_item AS a

LEFT OUTER JOIN .mark AS m
ON (a.mark_id = m.mark_id)

WHERE a.menu_item_category_id = b.menu_item_category_id AND a.menu_item_id = c.menu_item_id AND
c.menu_item_variant_type_id = d.menu_item_variant_type_id AND d.is_hidden = 'false' AND
c.size_id = e.size_id AND a.restaurant_id = f.restaurant_id AND f.restaurant_id = 1528 AND
(a.menu_item_category_id = NULL OR NULL IS NULL)

AND c.menu_item_variant_id = (SELECT min(menu_item_variant_id)
FROM .menu_item_variant
WHERE menu_item_id = a.menu_item_id AND deleted = 'N'
LIMIT 1) AND a.active = 'Y'
AND (CONCAT_WS('', ',', a.hidden_branch_ids, ',') NOT LIKE CONCAT_WS('', '%,4191,%') OR
NULL IS NULL)
AND .is_menu_item_available(a.menu_item_id, 'Y') = 'Y'

ORDER BY a.row_order, menu_item_id;

--Ayub

Вложения

waiting_client_write.JPG

Re: waiting for client write

От

Magnus Hagander

Дата:

09 июня 2021 г., 17:49:38

On Wed, Jun 9, 2021 at 4:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:
>
> attached is the screenshot of RDS performance insights for AWS and it shows high waiting client writes. The api
performanceis slow. I read that this might be due to IOPS on RDS. However we have 80k IOPS on this test RDS.

>

ClientWrite means Postgres is waiting on the *network* sending the
reply back to the client, it is unrelated to I/O. So either your
client isn't consuming the response fast enough, or the network
between them is too slow or shaped.

-- 
 Magnus Hagander
 Me: https://www.hagander.net/
 Work: https://www.redpill-linpro.com/

Re: waiting for client write

От

Ayub Khan

Дата:

09 июня 2021 г., 21:59:17

@Magnus

There is an EC2 tomcat server which communicates to postgresql. This is a replica of our production server except that in this case the test database is postgres RDS and our production is running oracle on EC2 instance.

On Wed, Jun 9, 2021 at 5:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:

--------------------------------------------------------------------

Sun Certified Enterprise Architect 1.5
Sun Certified Java Programmer 1.4
Microsoft Certified Systems Engineer 2000
http://in.linkedin.com/pub/ayub-khan/a/811/b81

mobile:+966-502674604

----------------------------------------------------------------------
It is proved that Hard Work and kowledge will get you close but attitude will get you there. However, it's the Love
of God that will put you over the top!!

Re: waiting for client write

От

Ayub Khan

Дата:

10 июня 2021 г., 11:06:03

I did profiling of the application and it seems most of the CPU consumption is for executing the stored procedure. Attached is the screenshot of the profile

--Ayub

On Wed, Jun 9, 2021 at 5:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:

--------------------------------------------------------------------

Sun Certified Enterprise Architect 1.5
Sun Certified Java Programmer 1.4
Microsoft Certified Systems Engineer 2000
http://in.linkedin.com/pub/ayub-khan/a/811/b81

mobile:+966-502674604

Вложения

application-profiler.JPG

Re: waiting for client write

От

Jeff Janes

Дата:

10 июня 2021 г., 18:40:01

On Thu, Jun 10, 2021 at 4:06 AM Ayub Khan <ayub.hp@gmail.com> wrote:

That is of your tomcat server? If that is really a profile of your CPU time (rather than wall-clock time) then it seems pretty clear your problem is on the client side, so there isn't much that can be done about it on the database server.

Cheers,

Jeff

Re: waiting for client write

От

Vijaykumar Jain

Дата:

10 июня 2021 г., 19:58:59

Ayub,

Ideally when i have to deal with this,

i run a pgbench stress test locally on the db server on lo interface which does not suffer mtu / bandwidth saturation issues.

then run the same pgbench from a remote server in the same subnet as the app and record the results and compare.

that helps me get rid of any non standard client issues or network latency issues.

A typical case where people above are pointing to is

1) for ex. When I am in India and query a server in the US across WAN on a client like pgadmin (which may not handle loading million rows efficiently), I have a high chance of getting ClientWrite ,ClientRead wait events. ( Read client and or network issues )

Of course this is much worse than ec2 and db in the same region, but you get the point that you have to rule out sketchy networks between the servers.

Ideally an iperf like stress test can help to test bandwidth.

So if you can run pgbench from across some test servers and get consistent results, then you can come back with a reply that more people can help with.

pgbench

using a custom script

postgres@go:~/pgbench_example$ more pgbench.script

\set r1 random(0, 10000) -- you can use them below in queries as params like col = :r1

\set r2 random(0, 8000)

begin;

select random();

end;

-- put in any query that you use in jmeter between begin/end like above

-- select * from foo where (u1 = :r1 and u2 = :r2);

-- insert into foo values (:u1v, :u2v) on conflict do nothing;

-- update foo set u1 = :u1v where u2 = 100;

-- select pg_sleep(1);

and then run pgbench with the custom script

postgres@go:~/pgbench_example$ pgbench -c 10 -f ./pgbench.script -j 10 -n -T 30

transaction type: ./pgbench.script

scaling factor: 1

query mode: simple

number of clients: 10

number of threads: 10

duration: 30 s

number of transactions actually processed: 528984

latency average = 0.567 ms

tps = 17631.650584 (including connections establishing)

tps = 17642.174229 (excluding connections establishing)

Re: waiting for client write

От

Ayub Khan

Дата:

11 июня 2021 г., 19:28:26

Vijay,

Both tomcat and postgresql are on the same region as that of the database server. It is an RDS so I do not have shell access to it.

Jeff,

The tomcat profile is suggesting that it's waiting for a response from the database server.

Tomcat and RDS are in the same availability region as eu-central-1a

On Wed, Jun 9, 2021 at 5:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:

--------------------------------------------------------------------

Sun Certified Enterprise Architect 1.5
Sun Certified Java Programmer 1.4
Microsoft Certified Systems Engineer 2000
http://in.linkedin.com/pub/ayub-khan/a/811/b81

mobile:+966-502674604

Re: waiting for client write

От

Pavan Pusuluri

Дата:

11 июня 2021 г., 19:46:43

Hi Ayub

So, i understand the client are blocked waiting on a write to the database!

What does the blocked thread signature say?

Are you pre-creating any partitions?

Are you experiencing Timed outs??

What is the driver you are using now? If you are using Jdbc, can you update your driver to the latest version?

Regards

Pavan

On Fri, Jun 11, 2021, 11:28 AM Ayub Khan <ayub.hp@gmail.com> wrote:

Re: waiting for client write

От

Ranier Vilela

Дата:

11 июня 2021 г., 19:52:44

Em sex., 11 de jun. de 2021 às 13:28, Ayub Khan <ayub.hp@gmail.com> escreveu:

Can you post the results with: explain analyze?

EXPLAIN ANALYZE

SELECT ....

regards,

Ranier Vilela

Re: waiting for client write

От

Ayub Khan

Дата:

11 июня 2021 г., 19:59:28

Pavan,

In jProfiler , I see that most cpu is consumed when the Tomcat thread is stuck at PgPreparedStatement.execute. I am using version 42.2.16 of JDBC driver.

Ranier,

EXPLAIN ANALYZE

SELECT a.menu_item_id, a.menu_item_name, a.menu_item_category_id, b.menu_item_category_desc, c.menu_item_variant_id, c.menu_item_variant_type_id, c.price, c.size_id, c.parent_menu_item_variant_id, d.menu_item_variant_type_desc, e.size_desc, f.currency_code, a.image, a.mark_id, m.mark_name

 FROM menu_item_category AS b, menu_item_variant AS c, menu_item_variant_type AS d, item_size AS e, restaurant AS f, menu_item AS a

 LEFT OUTER JOIN mark AS m ON (a.mark_id = m.mark_id) WHERE a.menu_item_category_id = b.menu_item_category_id AND a.menu_item_id = c.menu_item_id AND c.menu_item_variant_type_id = d.menu_item_variant_type_id AND d.is_hidden = 'false' AND c.size_id = e.size_id AND a.restaurant_id = f.restaurant_id AND f.restaurant_id = 1528 AND (a.menu_item_category_id = NULL OR NULL IS NULL)

 AND c.menu_item_variant_id = (SELECT min(menu_item_variant_id) FROM menu_item_variant WHERE menu_item_id = a.menu_item_id AND deleted = 'N' limit 1) AND a.active = 'Y'
 AND (CONCAT_WS('', ',', a.hidden_branch_ids, ',') NOT LIKE CONCAT_WS('', '%,4191,%') OR NULL IS NULL)
AND is_menu_item_available(a.menu_item_id, 'Y') = 'Y'


Nested Loop Left Join  (cost=5.15..162.10 rows=1 width=148) (actual time=0.168..5.070 rows=89 loops=1)
  Join Filter: (a.mark_id = m.mark_id)
  Rows Removed by Join Filter: 267
  ->  Nested Loop  (cost=5.15..161.04 rows=1 width=144) (actual time=0.161..4.901 rows=89 loops=1)
        ->  Nested Loop  (cost=4.86..158.72 rows=1 width=148) (actual time=0.156..4.729 rows=89 loops=1)
              ->  Nested Loop  (cost=4.57..158.41 rows=1 width=140) (actual time=0.151..4.572 rows=89 loops=1)
                    ->  Nested Loop  (cost=4.28..158.10 rows=1 width=132) (actual time=0.145..4.378 rows=89 loops=1)
                          ->  Nested Loop  (cost=0.71..152.51 rows=1 width=95) (actual time=0.121..3.334 rows=89 loops=1)
                                ->  Index Scan using menu_item_restaurant_id on menu_item a  (cost=0.42..150.20 rows=1 width=83) (actual time=0.115..3.129 rows=89 loops=1)
                                      Index Cond: (restaurant_id = 1528)
"                                      Filter: ((active = 'Y'::bpchar) AND (is_menu_item_available(menu_item_id, 'Y'::bpchar) = 'Y'::bpchar))"
                                      Rows Removed by Filter: 194
                                ->  Index Scan using menu_item_category_pk on menu_item_category b  (cost=0.29..2.31 rows=1 width=20) (actual time=0.002..0.002 rows=1 loops=89)
                                      Index Cond: (menu_item_category_id = a.menu_item_category_id)
                          ->  Index Scan using menu_item_variant_pk on menu_item_variant c  (cost=3.57..5.59 rows=1 width=45) (actual time=0.002..0.002 rows=1 loops=89)
                                Index Cond: (menu_item_variant_id = (SubPlan 1))
                                Filter: (a.menu_item_id = menu_item_id)
                                SubPlan 1
                                  ->  Limit  (cost=3.13..3.14 rows=1 width=8) (actual time=0.008..0.008 rows=1 loops=89)
                                        ->  Aggregate  (cost=3.13..3.14 rows=1 width=8) (actual time=0.008..0.008 rows=1 loops=89)
                                              ->  Index Scan using "idx$$_023a0001" on menu_item_variant  (cost=0.43..3.11 rows=8 width=8) (actual time=0.003..0.007 rows=7 loops=89)
                                                    Index Cond: (menu_item_id = a.menu_item_id)
                                                    Filter: (deleted = 'N'::bpchar)
                                                    Rows Removed by Filter: 4
                    ->  Index Scan using menu_item_variant_type_pk on menu_item_variant_type d  (cost=0.29..0.31 rows=1 width=16) (actual time=0.002..0.002 rows=1 loops=89)
                          Index Cond: (menu_item_variant_type_id = c.menu_item_variant_type_id)
                          Filter: ((is_hidden)::text = 'false'::text)
              ->  Index Scan using size_pk on item_size e  (cost=0.29..0.31 rows=1 width=16) (actual time=0.001..0.001 rows=1 loops=89)
                    Index Cond: (size_id = c.size_id)
        ->  Index Scan using "restaurant_idx$$_274b003d" on restaurant f  (cost=0.29..2.30 rows=1 width=12) (actual time=0.001..0.001 rows=1 loops=89)
              Index Cond: (restaurant_id = 1528)
  ->  Seq Scan on mark m  (cost=0.00..1.03 rows=3 width=12) (actual time=0.000..0.001 rows=3 loops=89)
Planning Time: 2.078 ms
Execution Time: 5.141 ms

On Wed, Jun 9, 2021 at 5:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:

--------------------------------------------------------------------

Sun Certified Enterprise Architect 1.5
Sun Certified Java Programmer 1.4
Microsoft Certified Systems Engineer 2000
http://in.linkedin.com/pub/ayub-khan/a/811/b81

mobile:+966-502674604

Re: waiting for client write

От

Ranier Vilela

Дата:

11 июня 2021 г., 20:37:53

Em sex., 11 de jun. de 2021 às 13:59, Ayub Khan <ayub.hp@gmail.com> escreveu:

Pavan,

In jProfiler , I see that most cpu is consumed when the Tomcat thread is stuck at PgPreparedStatement.execute. I am using version 42.2.16 of JDBC driver.

Ranier,

EXPLAIN ANALYZE

SELECT a.menu_item_id, a.menu_item_name, a.menu_item_category_id, b.menu_item_category_desc, c.menu_item_variant_id, c.menu_item_variant_type_id, c.price, c.size_id, c.parent_menu_item_variant_id, d.menu_item_variant_type_desc, e.size_desc, f.currency_code, a.image, a.mark_id, m.mark_name

 FROM menu_item_category AS b, menu_item_variant AS c, menu_item_variant_type AS d, item_size AS e, restaurant AS f, menu_item AS a

 LEFT OUTER JOIN mark AS m ON (a.mark_id = m.mark_id) WHERE a.menu_item_category_id = b.menu_item_category_id AND a.menu_item_id = c.menu_item_id AND c.menu_item_variant_type_id = d.menu_item_variant_type_id AND d.is_hidden = 'false' AND c.size_id = e.size_id AND a.restaurant_id = f.restaurant_id AND f.restaurant_id = 1528 AND (a.menu_item_category_id = NULL OR NULL IS NULL)

 AND c.menu_item_variant_id = (SELECT min(menu_item_variant_id) FROM menu_item_variant WHERE menu_item_id = a.menu_item_id AND deleted = 'N' limit 1) AND a.active = 'Y'
 AND (CONCAT_WS('', ',', a.hidden_branch_ids, ',') NOT LIKE CONCAT_WS('', '%,4191,%') OR NULL IS NULL)
AND is_menu_item_available(a.menu_item_id, 'Y') = 'Y'


Nested Loop Left Join  (cost=5.15..162.10 rows=1 width=148) (actual time=0.168..5.070 rows=89 loops=1)
  Join Filter: (a.mark_id = m.mark_id)
  Rows Removed by Join Filter: 267
  ->  Nested Loop  (cost=5.15..161.04 rows=1 width=144) (actual time=0.161..4.901 rows=89 loops=1)
        ->  Nested Loop  (cost=4.86..158.72 rows=1 width=148) (actual time=0.156..4.729 rows=89 loops=1)
              ->  Nested Loop  (cost=4.57..158.41 rows=1 width=140) (actual time=0.151..4.572 rows=89 loops=1)
                    ->  Nested Loop  (cost=4.28..158.10 rows=1 width=132) (actual time=0.145..4.378 rows=89 loops=1)
                          ->  Nested Loop  (cost=0.71..152.51 rows=1 width=95) (actual time=0.121..3.334 rows=89 loops=1)
                                ->  Index Scan using menu_item_restaurant_id on menu_item a  (cost=0.42..150.20 rows=1 width=83) (actual time=0.115..3.129 rows=89 loops=1)
                                      Index Cond: (restaurant_id = 1528)
"                                      Filter: ((active = 'Y'::bpchar) AND (is_menu_item_available(menu_item_id, 'Y'::bpchar) = 'Y'::bpchar))"
                                      Rows Removed by Filter: 194
                                ->  Index Scan using menu_item_category_pk on menu_item_category b  (cost=0.29..2.31 rows=1 width=20) (actual time=0.002..0.002 rows=1 loops=89)
                                      Index Cond: (menu_item_category_id = a.menu_item_category_id)
                          ->  Index Scan using menu_item_variant_pk on menu_item_variant c  (cost=3.57..5.59 rows=1 width=45) (actual time=0.002..0.002 rows=1 loops=89)
                                Index Cond: (menu_item_variant_id = (SubPlan 1))
                                Filter: (a.menu_item_id = menu_item_id)
                                SubPlan 1
                                  ->  Limit  (cost=3.13..3.14 rows=1 width=8) (actual time=0.008..0.008 rows=1 loops=89)
                                        ->  Aggregate  (cost=3.13..3.14 rows=1 width=8) (actual time=0.008..0.008 rows=1 loops=89)
                                              ->  Index Scan using "idx$$_023a0001" on menu_item_variant  (cost=0.43..3.11 rows=8 width=8) (actual time=0.003..0.007 rows=7 loops=89)
                                                    Index Cond: (menu_item_id = a.menu_item_id)
                                                    Filter: (deleted = 'N'::bpchar)
                                                    Rows Removed by Filter: 4
                    ->  Index Scan using menu_item_variant_type_pk on menu_item_variant_type d  (cost=0.29..0.31 rows=1 width=16) (actual time=0.002..0.002 rows=1 loops=89)
                          Index Cond: (menu_item_variant_type_id = c.menu_item_variant_type_id)
                          Filter: ((is_hidden)::text = 'false'::text)
              ->  Index Scan using size_pk on item_size e  (cost=0.29..0.31 rows=1 width=16) (actual time=0.001..0.001 rows=1 loops=89)
                    Index Cond: (size_id = c.size_id)
        ->  Index Scan using "restaurant_idx$$_274b003d" on restaurant f  (cost=0.29..2.30 rows=1 width=12) (actual time=0.001..0.001 rows=1 loops=89)
              Index Cond: (restaurant_id = 1528)
  ->  Seq Scan on mark m  (cost=0.00..1.03 rows=3 width=12) (actual time=0.000..0.001 rows=3 loops=89)
Planning Time: 2.078 ms
Execution Time: 5.141 ms

My guess is a bad planner (or slow planner) because of wrong or inconsistent parameters.

You must define precise parameters before calling a Prepared Statement or Planner will try to guess to do the best.

But this is a simple "guess" and can be completely wrong.

regards,

Ranier Vilela

Re: waiting for client write

От

Ayub Khan

Дата:

11 июня 2021 г., 20:59:07

Ranier,

I tried to VACCUM ANALYZE the tables involved multiple times and also tried the statistics approach as well

Pavan,

I upgraded to 42.2.21 version of jdbc driver and using HikariCp connection pool management 3.1.0

jProfiler shows the threads are stuck with high cpu usage on.

org.postgresql.jdbc.PgPreparedStatement.execute ,

below is the java code which calls postgresql

Connection con = null;

CallableStatement callableStatement = null;
ResultSet rs = null;
ResultSet rs1 = null;
PreparedStatement ps = null;
try {
con = connectionManager.getConnetion();

con.setAutoCommit(false);

callableStatement = con.prepareCall("call menu_pkg$get_menu_items_p_new(?,?,?,?,?,?)");
if (catId == 0)
callableStatement.setNull(2, Types.BIGINT);
else
callableStatement.setLong(2, catId);
callableStatement.setString(3, "Y");

if (branchId == 0)
callableStatement.setString(4, null);
else
callableStatement.setLong(4, branchId);

callableStatement.setNull(5, Types.OTHER);
callableStatement.setNull(6, Types.OTHER);
callableStatement.registerOutParameter(5, Types.OTHER);
callableStatement.registerOutParameter(6, Types.OTHER);
callableStatement.execute();
rs = (ResultSet) callableStatement.getObject(5);
rs1 = (ResultSet) callableStatement.getObject(6);
MenuMobile menuMobile;

try {
while (rs.next()) {

//process rs
}
MenuCombo menuCombo;
while (rs1.next()) {
//process rs1
}

menuMobileListCombo.setMenuComboList(menuComboList);
menuMobileListCombo.setMenuMobileList(menuMobileList);
} catch (SQLException e) {
LOG.error(e.getLocalizedMessage(), e);
}

con.commit();
con.setAutoCommit(true);
} catch (SQLException e) {
LOG.error(e.getLocalizedMessage(), e);
throw e;
} finally {
if (rs != null)
rs.close();
if (rs1 != null)
rs1.close();
if (ps != null)
ps.close();

if (callableStatement != null) callableStatement.close();
if (con != null) con.close();
}
return menuMobileListCombo;
}

On Wed, Jun 9, 2021 at 5:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:

--------------------------------------------------------------------

Sun Certified Enterprise Architect 1.5
Sun Certified Java Programmer 1.4
Microsoft Certified Systems Engineer 2000
http://in.linkedin.com/pub/ayub-khan/a/811/b81

mobile:+966-502674604

Re: waiting for client write

От

Ranier Vilela

Дата:

11 июня 2021 г., 21:03:03

Em sex., 11 de jun. de 2021 às 14:59, Ayub Khan <ayub.hp@gmail.com> escreveu:

Ayub you can try by the network side:

https://stackoverflow.com/questions/50298447/postgres-jdbc-client-getting-stuck-at-reading-from-socket

" We found out that this was caused by the database server's MTU setting.

MTU was set to 9000 by default and resulted in packet loss. Changing it to 1500 resolved the issue."

regards,

Ranier Vilela

Re: waiting for client write

От

Ayub Khan

Дата:

11 июня 2021 г., 21:19:19

Ranier,

I verified the link you gave and also checked AWS documentation and found the exact output as shown in AWS:

https://docs.aws.amazon.com/AWSEC2/latest/UserGuide/network_mtu.html

[ec2-user ~]$ tracepath amazon.com 1?: [LOCALHOST]     pmtu 9001 1:  ip-xxx-xx-xx-1.us-west-1.compute.internal (xxx.xx.xx.x)   0.187ms pmtu 1500

Should the LOCALHOST pmtu needs to be updated to 1500 ?

On Wed, Jun 9, 2021 at 5:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:

--------------------------------------------------------------------

Sun Certified Enterprise Architect 1.5
Sun Certified Java Programmer 1.4
Microsoft Certified Systems Engineer 2000
http://in.linkedin.com/pub/ayub-khan/a/811/b81

mobile:+966-502674604

Re: waiting for client write

От

Ranier Vilela

Дата:

11 июня 2021 г., 21:25:04

Em sex., 11 de jun. de 2021 às 15:19, Ayub Khan <ayub.hp@gmail.com> escreveu:

Or us-west-1.compute.internal should be set to 9000.

I think both must match. 9000 are jumbo frames.

The bigger the better.

Try switching to 9000 first and 1500 if it does not work.

regards,

Ranier Vilela

Re: waiting for client write

От

Ayub Khan

Дата:

11 июня 2021 г., 22:45:27

Ranier,

Both production and test vms are running on Ubuntu:

the below command when executed from client VM shows that its using PMTU 9001.

# tracepath dns-name-of-rds
1?: [LOCALHOST] pmtu 9001

On Wed, Jun 9, 2021 at 5:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:

--------------------------------------------------------------------

Sun Certified Enterprise Architect 1.5
Sun Certified Java Programmer 1.4
Microsoft Certified Systems Engineer 2000
http://in.linkedin.com/pub/ayub-khan/a/811/b81

mobile:+966-502674604

Re: waiting for client write

От

Jeff Janes

Дата:

12 июня 2021 г., 00:58:50

On Fri, Jun 11, 2021 at 12:28 PM Ayub Khan <ayub.hp@gmail.com> wrote:

But waiting for a response should consume zero CPU, that is why I wonder if this is a CPU profile or a wall-time profile.

I don't think that that necessarily guarantees high network performance. Some EC2 server classes have better networking than others. And if the server says it is waiting for the client, and the client says it is waiting server (assuming that that is really what it is saying), then what else could it be but the network?

Cheers,

Jeff

Re: waiting for client write

От

Ayub Khan

Дата:

12 июня 2021 г., 01:06:20

Jeff,

Both tomcat vm and RDS vms have 25Gbps

Postgresql Db class is db.r6g.16xlarge

Tomcat vm is c5.9xlarge

--Ayub

On Wed, 9 Jun 2021, 17:47 Ayub Khan, <ayub.hp@gmail.com> wrote:

Re: waiting for client write

От

Ayub Khan

Дата:

12 июня 2021 г., 11:19:57

Ranier,

This issue is only with queries which are slow, if it's an MTU issue then it should be with all the APIs.

I tried on Aurora db and I see same plan and also same slowness

On Wed, 9 Jun 2021, 17:47 Ayub Khan, <ayub.hp@gmail.com> wrote:

Re: waiting for client write

От

Ranier Vilela

Дата:

12 июня 2021 г., 15:03:58

Em sáb., 12 de jun. de 2021 às 05:20, Ayub Khan <ayub.hp@gmail.com> escreveu:

I think it is more indicative that the problem is in the network.
Despite having a proposed solution (MTU), you still have to ensure that the main problem happens (*packet loss*).

regards,

Ranier Vilela

Re: waiting for client write

От

Vijaykumar Jain

Дата:

12 июня 2021 г., 15:04:39

since you are willing to try out options :)

if your setup runs the same test plan queries on jmeter against oracle and postgresql

and only postgresql shows waits or degraded performance I think this is more then simply network.

can you simply boot up an ec2 ubuntu/centos and install postgresql.

and run pgbench locally on the installed db with the same queries.

and run the same pgbench against RDS and share the results.

On Sat, 12 Jun 2021 at 13:50, Ayub Khan <ayub.hp@gmail.com> wrote:

Thanks,

Vijay

Mumbai, India

Re: waiting for client write

От

Ayub Khan

Дата:

12 июня 2021 г., 15:34:37

Ranier, Vijay,

Sure will try and check out pgbench and MTU

--Ayub

On Wed, 9 Jun 2021, 17:47 Ayub Khan, <ayub.hp@gmail.com> wrote:

Re: waiting for client write

От

Ayub Khan

Дата:

13 июня 2021 г., 17:00:23

Ranier,

I did the MTU change and it did seem to bring down the clientWrite waits to half.

The change I did was to enable ICMP to have Destination Unreachable fragmentation needed and DF set

"When there is a difference in the MTU size in the network between two hosts, first make sure that your network settings don't block path MTU discovery (PMTUD). PMTUD enables the receiving host to respond to the originating host with the following ICMP message: Destination Unreachable: fragmentation needed and DF set (ICMP Type 3, Code 4). This message instructs the originating host to use the lowest MTU size along the network path to resend the request. "

https://docs.aws.amazon.com/redshift/latest/mgmt/connecting-drop-issues.html

Vijay,

Below is the pgbench result which was executed from the remote instance pointing to RDS

postgres@localhost:/archive$ pgbench -h pg-cluster -p 5432 -U testuser -c 50 -j 2 -P 60 -T 600 testdb -f /archive/test.sql
starting vacuum...pgbench: error: ERROR: relation "pgbench_branches" does not exist
pgbench: (ignoring this error and continuing anyway)
pgbench: error: ERROR: relation "pgbench_tellers" does not exist
pgbench: (ignoring this error and continuing anyway)
pgbench: error: ERROR: relation "pgbench_history" does not exist
pgbench: (ignoring this error and continuing anyway)
end.
progress: 60.0 s, 18.3 tps, lat 2631.655 ms stddev 293.592
progress: 120.0 s, 19.6 tps, lat 2533.271 ms stddev 223.722
progress: 180.0 s, 20.3 tps, lat 2446.050 ms stddev 158.397
progress: 240.1 s, 19.2 tps, lat 2575.506 ms stddev 292.418
progress: 300.0 s, 20.0 tps, lat 2482.908 ms stddev 181.770
progress: 360.0 s, 22.1 tps, lat 2245.147 ms stddev 110.855
progress: 420.0 s, 20.7 tps, lat 2397.270 ms stddev 289.324
progress: 480.0 s, 18.8 tps, lat 2625.595 ms stddev 240.250
progress: 540.0 s, 20.1 tps, lat 2467.336 ms stddev 133.121
progress: 600.0 s, 20.2 tps, lat 2455.824 ms stddev 137.976
transaction type: /archive/test.sql
scaling factor: 1
query mode: simple
number of clients: 50
number of threads: 2
duration: 600 s
number of transactions actually processed: 12007
latency average = 2480.042 ms
latency stddev = 242.243 ms
tps = 19.955602 (including connections establishing)
tps = 19.955890 (excluding connections establishing)

On Wed, Jun 9, 2021 at 5:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:

--------------------------------------------------------------------

Sun Certified Enterprise Architect 1.5
Sun Certified Java Programmer 1.4
Microsoft Certified Systems Engineer 2000
http://in.linkedin.com/pub/ayub-khan/a/811/b81

mobile:+966-502674604

Re: waiting for client write

От

Vijaykumar Jain

Дата:

13 июня 2021 г., 19:30:29

thanks.

>latency average = 2480.042 ms

that latency is pretty high, even after changing the mtu ? for a query that takes 5ms to run (from your explain analyze above) and returns a few 100 rows.

so it does look like a network latency, but it seems strange when you said the same query from the same ec2 host ran fast against oracle compared to postgres RDS.

So oracle and RDS on vms with separate mtu setting ?

i was tried to simulate issues with the client if any :),

Slow ClientWrites · Issue #2480 · brianc/node-postgres (github.com)

Some intial performance work by brianc · Pull Request #2031 · brianc/node-postgres (github.com)

ClientRead statement_timeout · Issue #1952 · brianc/node-postgres (github.com)

I tried to play around with FEBE protocols to delay flush sync etc, but could not simulate clientwrite wait event :(. Sorry.

and i am not touching java :)

I was asking for a run like this, with -r that would have shown latency per statement. but anyways.

Below I make use of tc (traffic control) to add a delay to my lo interface, and check how pgbench runs vary with increased latency at interface.

useless for your case, but i use this to tell dev when they have slot queries if, roundtrip delay is high, it is not a pg fault :)

postgres@db:~/playground$ sudo tc -s qdisc | head -3

qdisc noqueue 0: dev lo root refcnt 2

Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)

backlog 0b 0p requeues 0

postgres@db:~/playground$ sudo tc qdisc add dev lo root netem delay 100ms # add a delay on lo of 100ms via tc module

postgres@db:~/playground$ sudo tc -s qdisc | head -3

qdisc netem 8007: dev lo root refcnt 2 limit 1000 delay 100.0ms

Sent 8398 bytes 15 pkt (dropped 0, overlimits 0 requeues 0)

backlog 0b 0p requeues 0

postgres@db:~/playground$ pgbench -c 2 -C -j 2 -n -P 2 -T 10 -r -f pgbench.test -h 127.0.0.1

progress: 2.0 s, 1.0 tps, lat 603.211 ms stddev 0.007

progress: 4.2 s, 1.8 tps, lat 602.838 ms stddev 0.101

progress: 6.0 s, 1.1 tps, lat 603.730 ms stddev 0.034

progress: 8.0 s, 2.0 tps, lat 603.058 ms stddev 0.081

progress: 10.3 s, 1.8 tps, lat 600.852 ms stddev 0.030

pgbench (PostgreSQL) 14.0

transaction type: pgbench.test

scaling factor: 1

query mode: simple

number of clients: 2

number of threads: 2

duration: 10 s

number of transactions actually processed: 18

latency average = 602.357 ms

latency stddev = 1.112 ms

average connection time = 605.499 ms

tps = 1.655749 (including reconnection times)

statement latencies in milliseconds:

200.672 begin;

200.797 select 1;

200.917 end;

postgres@db:~/playground$ sudo tc qdisc del dev lo root netem # remove delay

postgres@db:~/playground$ sudo tc -s qdisc | head -3

qdisc noqueue 0: dev lo root refcnt 2

Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)

backlog 0b 0p requeues 0

postgres@db:~/playground$ pgbench -c 2 -C -j 2 -n -P 2 -T 10 -r -f pgbench.test -h 127.0.0.1

progress: 2.0 s, 1272.4 tps, lat 0.200 ms stddev 0.273

progress: 4.0 s, 1155.3 tps, lat 0.306 ms stddev 0.304

progress: 6.0 s, 1241.7 tps, lat 0.261 ms stddev 0.290

progress: 8.0 s, 1508.6 tps, lat 0.150 ms stddev 0.140

progress: 10.0 s, 1172.7 tps, lat 0.292 ms stddev 0.302

pgbench (PostgreSQL) 14.0

transaction type: pgbench.test

scaling factor: 1

query mode: simple

number of clients: 2

number of threads: 2

duration: 10 s

number of transactions actually processed: 12704

latency average = 0.236 ms

latency stddev = 0.271 ms

average connection time = 1.228 ms

tps = 1270.314254 (including reconnection times)

statement latencies in milliseconds:

0.074 begin;

0.115 select 1;

0.048 end;

Re: waiting for client write

От

Ayub Khan

Дата:

13 июня 2021 г., 20:00:17

Vijay,

I did not change the MTU on the network interface but created incoming rule on the security group as per the below documentation:

PMTUD enables the receiving host to respond to the originating host with the following ICMP message: Destination Unreachable: fragmentation needed and DF set (ICMP Type 3, Code 4). This message instructs the originating host to use the lowest MTU size along the network path to resend the request. Without this negotiation, packet drop can occur because the request is too large for the receiving host to accept.

I also did another test, instead of using RDS, installed postgresql on a similar VM as that of where oracle is installed and tested it. Now even when both client and postgresql VMs have the same MTU settings still in the pg activity table I could see clientwrite waits.

-Ayub

On Wed, Jun 9, 2021 at 5:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:

--------------------------------------------------------------------

Sun Certified Enterprise Architect 1.5
Sun Certified Java Programmer 1.4
Microsoft Certified Systems Engineer 2000
http://in.linkedin.com/pub/ayub-khan/a/811/b81

mobile:+966-502674604

Re: waiting for client write

От

Ayub Khan

Дата:

14 июня 2021 г., 08:02:17

Vijay,

below is the benchmark result when executed against bench_mark database instead of running the test with slow query on the application database. This shows that it might not be an issue with MTU but some issue with the application database itself and the query.

postgres@localhost:~$ pgbench -h test-cluster -p 5432 -U testuser -c 50 -j 2 -P 60 -T 600 bench_mark
starting vacuum...end.
progress: 60.0 s, 17830.3 tps, lat 2.765 ms stddev 0.632
progress: 120.0 s, 18450.3 tps, lat 2.681 ms stddev 0.582
progress: 180.0 s, 18405.0 tps, lat 2.688 ms stddev 0.588
progress: 240.0 s, 17087.9 tps, lat 2.897 ms stddev 0.717
progress: 300.0 s, 18280.6 tps, lat 2.706 ms stddev 0.595
progress: 360.0 s, 18433.9 tps, lat 2.683 ms stddev 0.582
progress: 420.0 s, 18308.4 tps, lat 2.702 ms stddev 0.599
progress: 480.0 s, 18156.7 tps, lat 2.725 ms stddev 0.615
progress: 540.0 s, 16803.3 tps, lat 2.946 ms stddev 0.764
progress: 600.0 s, 18266.6 tps, lat 2.708 ms stddev 0.602
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 150
query mode: simple
number of clients: 50
number of threads: 2
duration: 600 s
number of transactions actually processed: 10801425
latency average = 2.747 ms
latency stddev = 0.635 ms
tps = 18001.935315 (including connections establishing)
tps = 18002.205940 (excluding connections establishing)

On Wed, Jun 9, 2021 at 5:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:

--------------------------------------------------------------------

Sun Certified Enterprise Architect 1.5
Sun Certified Java Programmer 1.4
Microsoft Certified Systems Engineer 2000
http://in.linkedin.com/pub/ayub-khan/a/811/b81

mobile:+966-502674604

Re: waiting for client write

От

Ayub Khan

Дата:

15 июня 2021 г., 18:43:16

Would it be a cursor issue on postgres, as there seems to be a difference in how cursors are handled in postgres and Oracle database. It seems cursors are returned as buffers to the client side. Below are the steps we take from jdbc side

below is the stored procedure code:

CREATE OR REPLACE PROCEDURE ."menu_pkg$get_menu_items_p_new"(
i_restaurant_id bigint,
i_category_id bigint,
i_check_availability text,
i_branch_id bigint,
INOUT o_items refcursor,
INOUT o_combo refcursor)
LANGUAGE 'plpgsql'

AS $BODY$

BEGIN

OPEN o_items FOR

SELECT

a.menu_item_id, a.menu_item_name, a.menu_item_category_id, b.menu_item_category_desc, c.menu_item_variant_id, c.menu_item_variant_type_id, c.price, c.size_id, c.parent_menu_item_variant_id, d.menu_item_variant_type_desc, e.size_desc, f.currency_code, a.image, a.mark_id, m.mark_name

FROM .menu_item_category AS b, .menu_item_variant AS c, .menu_item_variant_type AS d, .item_size AS e, .restaurant AS f, .menu_item AS a

LEFT OUTER JOIN .mark AS m ON (a.mark_id = m.mark_id) WHERE a.menu_item_category_id = b.menu_item_category_id AND a.menu_item_id = c.menu_item_id
AND c.menu_item_variant_type_id = d.menu_item_variant_type_id AND d.is_hidden = 'false' AND c.size_id = e.size_id AND a.restaurant_id = f.restaurant_id AND f.restaurant_id = i_restaurant_id AND (a.menu_item_category_id = i_category_id OR i_category_id IS NULL) AND c.menu_item_variant_id =
(SELECT MIN(menu_item_variant_id) FROM .menu_item_variant WHERE menu_item_id = a.menu_item_id AND deleted = 'N') AND a.active = 'Y' AND (CONCAT_WS('', ',', a.hidden_branch_ids, ',') NOT LIKE CONCAT_WS('', '%,', i_branch_id, ',%') OR i_branch_id IS NULL) AND .is_menu_item_available(a.menu_item_id, i_check_availability) = 'Y'

ORDER BY a.row_order, menu_item_id;

OPEN o_combo FOR

SELECT

mc.*, f.currency_code, (CASE

WHEN blob_id IS NOT NULL THEN 'Y'

ELSE 'N'

END) AS has_image

FROM .menu_combo AS mc, .restaurant AS f

WHERE mc.restaurant_id = i_restaurant_id AND active = 'Y' AND mc.restaurant_id = f.restaurant_id AND (menu_item_category_id = i_category_id OR i_category_id IS NULL)

ORDER BY combo_id;

END;

$BODY$;

open connection
set auto commit to false
create callable statement
execute the call
get the results
set autocommit to true
close the resultset,callable statement and connection

On Wed, Jun 9, 2021 at 5:47 PM Ayub Khan <ayub.hp@gmail.com> wrote:

--------------------------------------------------------------------

Sun Certified Enterprise Architect 1.5
Sun Certified Java Programmer 1.4
Microsoft Certified Systems Engineer 2000
http://in.linkedin.com/pub/ayub-khan/a/811/b81

mobile:+966-502674604

Re: waiting for client write

От

Vijaykumar Jain

Дата:

15 июня 2021 г., 20:22:23

On Tue, 15 Jun 2021 at 21:13, Ayub Khan <ayub.hp@gmail.com> wrote:
>
>
> Would it be a cursor issue on postgres, as there seems to be a difference in how cursors are handled in postgres and Oracle database. It seems cursors are returned as buffers to the client side. Below are the steps we take from jdbc side

i did this as well to understand what caused clientwrite wait event.
open a cursor, fetch some rows but not all, and not close them. run this for multiple connections.
All i got was some client read, but no client write.
I think i might have to intentionally mangle some response packets from server to client to see if that helps,
but I was thinking i am diverting from the main problem.
unless we have a reproducible dataset to work on, i was not sure it was helping.

If you can have some sample table(s), and can create a proc on the same lines as above to query data, and still get the same issues.
that would be helpful to debug further.

else,
you may have to give a stacktrace using pstack or gdb / perf etc to help figure out what is going on at code level.

Profiling_with_perf
trace-query-processing-internals-with-debugger

This may / may not help, but it'll help learn to eliminate noise :)

Вход в личный кабинет

Восстановление пароля

Подтверждение аккаунта

Изменение пароля

Обсуждение: waiting for client write

Вложения

Вложения