Oracle 1.22s timeout after packet retransmit on AIX server

asked 2018-04-12 16:26:04 +0000

TomLaBaude
112 ●22 ●30 ●42 https://debookee.com

updated 2018-04-12 16:34:44 +0000

I have an issue of slowness on an Oracle base after observing packet losses, but don't really understand how to pinpoint more between Oracle and the AIX server TCP stack.

No pcap unfortunately, only this screenshot. Trace is taken with a tcpdump on the server.

C:\fakepath\Snap4.png

TCP baseline is:

Client sends request of 145 bytes
Server answers with 182 bytes in less than 1ms

Sometimes, packets are dropped on the way back from server to client, in that case:

Client sends request (#142)
Server sends answer (#150) in 0.14ms
After 200ms, client sends another time the request (#2357)
Server acks immediately (#2358)
After 1.22s, servers sends the answer (#11903), which is a retry of #150

1st action: identify packet drops on the network and lower them

1st conclusion of the 1.22 seconds: Oracle is responsible of this delay to reproduce a 2nd time the answer, and the TCP stack acks the 2nd requests so quickly, proving that it's not an AIX TCP stack problem, but an applicative one, and also presence of PSH flag in request.

But: Oracle logs show that Oracle is waiting for client for 1.5s and does only once the process of request in DB Retransmission of packet #11903 has the same sequence number that #150, so this means the packet #11903 is coming directly from the stack buffer, not a new answer of application.

So:

Why would the stack immediately ack the request without data if it retransmit directly the packet after?
Why would the stack wait for 1.22s before resending a packet it has in buffer?
And more important: where should I troubleshoot more? Tracing the process between AIX and Oracle?

Thanks for any feedback, Thomas

edit retag flag offensive close merge delete

Comments

My first thought was why is the client just sitting there after 2358? The server has ack'd the data. Then I realized that the first (150) was an ack + answer, and the second (2358) was only an ack. Server never gets a next request, so it finally times out and retransmits the ack + answer. My question is; is packet 11903 coming from tcp as a standard retransmit, or from the application because Oracle expects the client to make a new request? I'll be honest, I'm not sure. I want to say L7 since L4 has already achieved its goals, but I've never seen an Oracle server do that before.

Betty DuBois ( 2018-04-12 18:07:23 +0000 )edit

I don't think this is an answer, per se, so I'll just add my take as a comment here, but I suspect the problem is related to the bi-directional flow of data.

Frame 142: The Client sends 79 bytes of TCP payload and expects an ACK of 1732531716 from the Oracle Server. This frame also serves as an ACK to the data sent by the Server in Frame 120.
Frame 150: Server ACK's the 79 bytes the Client sent in Frame 142, but also sends 116 bytes of data and expects a corresponding ACK to these bytes from the Client.
Frame 2357: The Client obviously didn't receive the ACK (Frame 150), and at this point has no idea the Server attempted to send data as well, so after a 200ms timeout, the Client retransmits Frame 142.
Frame 2358: The Server sees the retransmission of Frame 142 ...

(more)

cmaynard ( 2018-04-12 18:46:30 +0000 )edit

@cmaynard. That 1.42 delta is what makes me think this is an Oracle issue vs. AIX. I agree with Chris, the tcp stack would have timed out much faster.

Betty DuBois ( 2018-04-12 18:52:28 +0000 )edit

Yes, maybe it seems to be an AIX behaviour. https://books.google.de/books?id=lHTJ...

Christian_R ( 2018-04-12 19:04:06 +0000 )edit

@TomLaBaude I would try to trace also next to the client side. To see both sides.

Christian_R ( 2018-04-12 20:27:22 +0000 )edit

add a comment

2 Answers

Sort by » oldest newest most voted

answered 2018-04-12 19:40:14 +0000

SYN-bit

18528 ●9 ●343 ●255 https://SYN-b.it

Hi Thomas, what are you doing, posting a screenshot??? and making me read RFC1323 all over again??? ;-)

My understanding of RFC1323 is that each packet gets a TSval and that the TSval of the original packet must be used in the retransmission as well. This makes it possible to detect whether a segment is a retransmission or a new segment after wrapped sequence numbers.

In this case, the retransmission of frame 142 (frame 2357) uses a new TSval. The client apparently did not save the original TSval (499841231) of the segment and supplied a new TSval (499841282) to the retransmission (the increase of the TSval suggests a TSclock with 4ms ticks). To the server, this is a new segment after wrapping sequence numbers, so it sends a DUP-ACK to indicate that it missed data. As this is the first DUP-ACK, no fast retransmit will be done and the RTO timer keeps ticking until it finaly sends a retransmission due to RTO (frame 11903).

So in this case I would say it is a bug in the client's TCP stack, not implementing RFC1323 correctly. What is the client's OS? Are you able to disable RFC1323 options for analysis's Sake (pun intended)? If so, I expect to see 200ms RTO's on the client which will be ingnored by the server as the data has already been ACKed. So no difference in your performance loss, but at least some validation of my theory :-)

Next to solving the packet loss issues, you might want to sit down with the Application developer and the DBadmin to increase the fetch-size as it looks like there is now a "one-row-response-at-a-time" policy. Since there is one packet to send, fast-retranmits will never be send so each loss results in an RTO of 1.4 sec. When data is tranmitted more in a stream (due to larger responses), DUP-ACK's will trigger FastRetransmits which will make the effect of packet-loss smaller. And as a bonus, the application might be performant on the WAN too!

edit flag offensive delete link

Comments

@SYN-bit: I understand the RFC1323 different:

Suppose the segment sequence: A.1, B.1, C.1, ..., Z.1 has been sent, where the letter indicates the sequence number and the digit represents the timestamp. Suppose also that segment B.1 has been lost. The timestamp in TS.TStamp is 1 (from A.1), so C.1, ..., Z.1 are considered acceptable and are queued. When B is retransmitted as segment B.2

I interpret it that way, that a retransmitted frame gots a new TsVal. Did I miss something?

Christian_R ( 2018-04-12 20:03:05 +0000 )edit

My understanding of RFC1323 is that each packet gets a TSval and that the TSval of the original packet must be used in the retransmission as well.

OK, I'm confused. You may very well be right, but can you indicate where that is stated? In reading Section 4 of RFC1323, I find on page 19 the following example:

Suppose the segment sequence: A.1, B.1, C.1, ..., Z.1 has
been sent, where the letter indicates the sequence number
and the digit represents the timestamp.  Suppose also that
segment B.1 has been lost.  The timestamp in TS.TStamp is
1 (from A.1), so C.1, ..., Z.1 are considered acceptable
and are queued.  When B is retransmitted as segment B.2
(using the latest timestamp), it fills the hole and causes
all the segments through Z to be acknowledged and passed
to the user.  The timestamps ...

(more)

cmaynard ( 2018-04-12 20:36:03 +0000 )edit

RFC 1323 is obsoleted by RFC 7323, but it looks like the same example is used in Section 5.3.

cmaynard ( 2018-04-12 20:41:46 +0000 )edit

Thanks @Christian_R for this AIX docs, I'll definitely have a look at the RTO which seems higher than common sense would expect it to be. @SYN-bit, I reproduced quickly a retransmit between Mac and Linux server with a changing TSVal, so not convinced on client bug, but your explanation of 1 to 1 req/answer which can't trigger Fast Retransmit is very valuable and makes it a worse case...

TomLaBaude ( 2018-04-12 22:17:21 +0000 )edit

OK guys, I stand corrected on the time stamp of the retransmission. The combination of the large RTO, no streaming data and some packet loss is enough to kill the performance...

SYN-bit ( 2018-04-13 01:27:33 +0000 )edit

see more comments

answered 2018-04-12 16:59:48 +0000

Jasper
24103 ●5 ●111 ●292 Düsseldorf, Germany

This clearly seems not to be a network issue, this is on the oracle side from what I can tell from the screenshot. The interaction between stack and application seems to be problematic here, and that may be hard to diagnose without doing some OS debugging...

edit flag offensive delete link

Comments

Yes, it probably is, which causes the "spurious" part of the "spurious retransmission" tag. But still, the oracle server doesn't behave right - it should be answering right away, not wait that long.

Jasper ( 2018-04-12 17:54:16 +0000 )edit

oops deleted comment: So to be complete: My original comment was; Couldn´t it be that frame #150 got lost.

Christian_R ( 2018-04-12 18:39:15 +0000 )edit

hm, I have only the explanation that maybe (But this is really only an assumption) frame #2358 is lost, too. And then the Oracle system runs into a huge RTO timer (around 1.4s). But I am really not sure, if that can be possible, due to the fact that the normal RTT is not that high here.

To see the 3way handshake would also be nice.

Christian_R ( 2018-04-12 18:52:45 +0000 )edit

add a comment

Your Answer

Please start posting anonymously - your entry will be published after you log in or create a new account.

Add Answer

Oracle 1.22s timeout after packet retransmit on AIX server

Comments

2 Answers

Comments

Comments

Your Answer

Question Tools

Stats

Related questions

Oracle 1.22s timeout after packet retransmit on AIX server edit

Comments

2 Answers

Comments

Comments

Your Answer

Question Tools

Stats

Related questions

Oracle 1.22s timeout after packet retransmit on AIX server