Sybase Database - performance issue in CT-library (ASE 12.5.1 on Linux)

Author

performance issue in CT-library (ASE 12.5.1 on Linux)

Matthias Apitz

2005-09-17, 1:23 pm

We're still struggling with an performance problem of our application
which already has been an issue on ASE 12.5.0.x but which get worser
on 12.5.1 on top of SuSE SLES server; the application uses ESQL/C
as connection layer to Sybase and debugging the connection between the
ESQL/C client (on top of CT-library) with the Linux tool strace, I get
more and more an idea, what's going on.

To bring you in the picture: the server has more then enough RAM and
the CPU-usage is always near idle, around 80% idle; there are only
around 10 connects on the ASE dataserver which has cache rates of 99.999%

So I went debugging the network connection (which is on localhost 127.0.0.1)
and I see the following disaster:

- for one typical operation of the application (which runs in a library
to borrow books and take them back) there is a need of overall 1100 ms;

- the application in this 1100 ms does 163 send socket calls to the
server and twice as much read calls to get the response from the
ASE; each turnaround is nearly always the same:

...
14:33:33.334557 send(5, " \17\1\0006\0\0\0\0#)
\0\0\0\20d35buchnoti
z_scr\10\0"..., 54, 0) = 54
14:33:33.339948 rt_sigprocmask(SIG_B
LOCK, [URG IO], [], 8) = 0
14:33:33.340025 rt_sigprocmask(SIG_S
ETMASK, [], NULL, 8) = 0
14:33:33.340065 read(5, "\4\1\0\33\0\0\0\0", 8) = 8
14:33:33.340107 rt_sigprocmask(SIG_B
LOCK, [URG IO], [], 8) = 0
14:33:33.340147 read(5, " \203\7\0\273\16!\0\3
\25\0\375\0\0\2\0\0\
0\0\0", 19) = 19
14:33:33.340231 rt_sigprocmask(SIG_S
ETMASK, [], NULL, 8) = 0
14:33:33.340269 rt_sigprocmask(SIG_B
LOCK, [URG IO], [], 8) = 0
14:33:33.340310 rt_sigprocmask(SIG_S
ETMASK, [], NULL, 8) = 0
14:33:33.340345 rt_sigprocmask(SIG_B
LOCK, [URG IO], [], 8) = 0
14:33:33.340386 rt_sigprocmask(SIG_S
ETMASK, [], NULL, 8) = 0
...

as you can see: one send(), followed by one read of 8 bytes and
a second read to get the real answer from ASE, anyway what it is;

as you can see too: each of this turn-around takes ~6 ms and
consequently 163 are taking ~1000 ms;

- but now have a look more deeper at the time between the send of
the data and the 1st rt_sigprocmask() and the 1st read():
5.3 ms are between the send() and the start(!) of the read, because
the tool strace always shows the time of the start of the sys-call;

What is the CT-layer doing in this long time before trying to
read the answer from ASE?

To test the network performance I wrote a small C pgm sending
data to localhost port 7 (echo) and reading back the data; this
looks much faster, like this on the same host where at the
same time the performance is bad:

15:41:00.243735 send(3, " aaaaaaaaaaaaaaaaaaaa
aaaaaaaaaaaa"..., 100, 0) = 100
15:41:00.243799 rt_sigprocmask(SIG_B
LOCK, [], [], 8) = 0
15:41:00.243853 rt_sigprocmask(SIG_S
ETMASK, [], [], 8) = 0
15:41:00.243904 read(3, " aaaaaaaaaaaaaaaaaaaa
aaaaaaaaaaaa"..., 100) = 100
15:41:00.243961 send(3, " aaaaaaaaaaaaaaaaaaaa
aaaaaaaaaaaa"..., 100, 0) = 100
15:41:00.244026 rt_sigprocmask(SIG_B
LOCK, [], [], 8) = 0
15:41:00.244079 rt_sigprocmask(SIG_S
ETMASK, [], [], 8) = 0
15:41:00.244130 read(3, " aaaaaaaaaaaaaaaaaaaa
aaaaaaaaaaaa"..., 100) = 100
15:41:00.244186 send(3, " aaaaaaaaaaaaaaaaaaaa
aaaaaaaaaaaa"..., 100, 0) = 100

So I think it must be something inside the CT-layer, no?

Thx in advance for any idea or hint

matthias

SybaseNeal

2005-09-22, 11:23 am

Hello,

That looks like CT-Library bug number 366805. It caused
the client to do two reads:
- The first read got the 8 byte header of the packet coming from the
server.
- The second read got the remainder of the packet coming from the
server.

This was fixed in 12.5.1 ESD#7 but I would recommend getting the latest
patch, ESD#10.

Thanks,
Neal

Matthias Apitz

2005-09-26, 3:23 am

"SybaseNeal" <nstack21@gmail.com> writes:

>Hello,

>That looks like CT-Library bug number 366805. It caused
>the client to do two reads:
>- The first read got the 8 byte header of the packet coming from the
>server.
>- The second read got the remainder of the packet coming from the
>server.

>This was fixed in 12.5.1 ESD#7 but I would recommend getting the latest
>patch, ESD#10.

>Thanks,
> Neal

Thanks for your follow-up. But the performance problem is not
caused by the two read-calls. The delay between the send and the
1st read of ~6 msec is causing the bad performance.

matthias

Pablo Sanchez

2005-09-26, 7:23 am

guru@revolucion.Sisis.de (Matthias Apitz) wrote in
news:dghg19$548$1@re
volucion.Sisis.de:

>
> So I think it must be something inside the CT-layer, no?
>
> Thx in advance for any idea or hint

Hi Matthias,

Have you set your ASE's "tcp no delay" setting to 1?

Cheers,
--
Pablo Sanchez - Blueoak Database Engineering, Inc
http://www.blueoakdb.com

SybaseNeal

2005-09-26, 1:23 pm

Hello,

If you are concerned about the time between the send() and the first
read()
that is being spent in rt_sigprocmask() you are likely running into
this bug:
333225 CTLIB: Non-threaded libraries were setting and
resetting the signal mask too frequently resulting
in reduced performance.

It is also fixed in 12.5.1 ESD#10.

Matthias Apitz

2005-09-28, 9:23 am

"SybaseNeal" <nstack21@gmail.com> writes:

>Hello,

>If you are concerned about the time between the send() and the first
>read()
>that is being spent in rt_sigprocmask() you are likely running into
>this bug:
> 333225 CTLIB: Non-threaded libraries were setting and
> resetting the signal mask too frequently resulting
> in reduced performance.

>It is also fixed in 12.5.1 ESD#10.

Hello,

Thanks for your feedback and yes, this is exactly what I'm concerned
about : the delay of 6-8 millisecs between send and read; one could
argument that 6-8 millisecs is not much, but if you have some 100
send/read pairs for a logical operation we are speeking about one
second...

Could you pls give (if you want by e-mail) some more information
about this case 333225; I can't locate it in Sybase' database and
our case number (11169515) is lightyears away from that number, maybe
they deleted old cases.

Thx

Matthias

SybaseNeal

2005-09-29, 3:23 am

That is not the case number, it is the bug number.
You need to upgrade to 12.5.1 ESD#10...
http://downloads.sybase.com

Matthias Apitz

2005-10-20, 8:23 pm

guru@revolucion.Sisis.de (Matthias Apitz) writes:

>We're still struggling with an performance problem of our application
>which already has been an issue on ASE 12.5.0.x but which get worser
>on 12.5.1 on top of SuSE SLES server; the application uses ESQL/C
>as connection layer to Sybase and debugging the connection between the
>ESQL/C client (on top of CT-library) with the Linux tool strace, I get
>more and more an idea, what's going on.

>To bring you in the picture: the server has more then enough RAM and
>the CPU-usage is always near idle, around 80% idle; there are only
>around 10 connects on the ASE dataserver which has cache rates of 99.999%

>So I went debugging the network connection (which is on localhost 127.0.0.1)
>and I see the following disaster:

>- for one typical operation of the application (which runs in a library
> to borrow books and take them back) there is a need of overall 1100 ms;

>- the application in this 1100 ms does 163 send socket calls to the
> server and twice as much read calls to get the response from the
> ASE; each turnaround is nearly always the same:

> ...
> 14:33:33.334557 send(5, " \17\1\0006\0\0\0\0#)
\0\0\0\20d35buchnoti
z_scr\10\0"..., 54, 0) = 54
> 14:33:33.339948 rt_sigprocmask(SIG_B
LOCK, [URG IO], [], 8) = 0
> 14:33:33.340025 rt_sigprocmask(SIG_S
ETMASK, [], NULL, 8) = 0
> 14:33:33.340065 read(5, "\4\1\0\33\0\0\0\0", 8) = 8
> 14:33:33.340107 rt_sigprocmask(SIG_B
LOCK, [URG IO], [], 8) = 0
> 14:33:33.340147 read(5, " \203\7\0\273\16!\0\3
\25\0\375\0\0\2\0\0\
0\0\0", 19) = 19
> 14:33:33.340231 rt_sigprocmask(SIG_S
ETMASK, [], NULL, 8) = 0
> 14:33:33.340269 rt_sigprocmask(SIG_B
LOCK, [URG IO], [], 8) = 0
> 14:33:33.340310 rt_sigprocmask(SIG_S
ETMASK, [], NULL, 8) = 0
> 14:33:33.340345 rt_sigprocmask(SIG_B
LOCK, [URG IO], [], 8) = 0
> 14:33:33.340386 rt_sigprocmask(SIG_S
ETMASK, [], NULL, 8) = 0
> ...

> as you can see: one send(), followed by one read of 8 bytes and
> a second read to get the real answer from ASE, anyway what it is;

> as you can see too: each of this turn-around takes ~6 ms and
> consequently 163 are taking ~1000 ms;

>- but now have a look more deeper at the time between the send of
> the data and the 1st rt_sigprocmask() and the 1st read():
> 5.3 ms are between the send() and the start(!) of the read, because
> the tool strace always shows the time of the start of the sys-call;

>What is the CT-layer doing in this long time before trying to
>read the answer from ASE?
...

To terminate this threat, because we found the answer, I want to add
the following things:

I was wrong in thinking 'What is the CT-layer doing in this long time before
trying to read the answer from ASE?'; the CT-layer did nothing because the
send(2) sys-call itself does not returned in this ~6 msecs, a idea which
never came into my mind before that a simple non blocking send of some
bytes could take this amount of time, but it is true;

and we found the reason why:

Sybase ASE server cycles in his queues this time, don't giving back
the CPU to OS and therefore no other process any chance for doing
usefull things, like reading the answer of ASE, for example;

there are two ways to avoid this problem: nice'ing the ASE process
or reducing the ASE dynamic tuneable 'runnable process search count'
from 2000 (DEFAULT) to some better value, currently I'm testing with 50
and our customer is happy.

Bottom line: if you have ASE on a single-CPU-system and want to have good
performance, you don't have to make ASE faster, but slower :-)

matthias

Sponsored Links