OpenEdge.Net library slow performance

Posted by toomaskask on 11-Apr-2017 08:46

Hi!

I am using Http Client (OE 11.6.2, OpenEdge.Net.pl library) to send GET requests to a server expecting a file (e.g. pdf as application/octet-stream) as a response.

Files under 1 mb arrive relatively fast, but for example a 20 mb file will arrive in around 5 minutes. Logging shows that the file is received in 8kb chunks, is that the cause of the delay and is that (=socket receive buffer) adjustable?

Using 'wget' or 'curl' takes ~2sec to get response back, this means that problem is not on server side.

Any idea how can I receive files quicker using HttpClient? 

BR

Toomas

OpenEdge Development - Forum

All Replies

Posted by Peter Judge on 11-Apr-2017 21:30

You can set the options on the socket while building the HttpClientLibrary and HttpClient. There are examples at github.com/.../set_options.p  on how to do this. In line 34 you’d set the ReceiveBufferSize to something larger than the 8k default.  You can also set the socket options that way.
 
I was looking through the sources because I had thought that the client waited for the socket to time out, but that shouldn’t be a problem in 11.6.2. If you turn logging on (logging-level = 6) , how many response-data-chunk files do you see in session:temp-dir? If there are all of them (the ~2500) after a few seconds and the client is just waiting, then that’s what the problem is and you should get to 11.6.3 .
 
 
 
 
 

Posted by Peter Judge on 11-Apr-2017 21:31

I just tested bumping up the receive buffer size from 8192 (0x2000) to 524288 (0x80000) bytes and saw times drop from ~65sec to ~15 sec.
 
The socket takes just a few millis to respond but it looks like the processing of that payload is what’s taking time (example below). Not a lot (15 or so millis per chunk) but that’ll add up when you’re dealing with ~2500 vs ~200 chunks.
 
[17/04/11@11:34:46.800-0400] P-001156 T-016324 1 4GL LogMgrWrtr     [O.Net DEBUG] ReadHandler: OK? Yes
 
---> [17/04/11@11:34:46.803-0400] P-001156 T-016324 1 4GL LogMgrWrtr     [O.Net DEBUG] ReadHandler: time(ms)=4
 
[17/04/11@11:34:46.806-0400] P-001156 T-016324 1 4GL LogMgrWrtr     [O.Net DEBUG] ReadHandler: size(b)=55200
[17/04/11@11:34:46.809-0400] P-001156 T-016324 1 4GL LogMgrWrtr     [O.Net DEBUG] CHUNK: NUM= 312
[17/04/11@11:34:46.813-0400] P-001156 T-016324 1 4GL LogMgrWrtr     [O.Net DEBUG] CHUNK: SIZE(b)= 524288
[17/04/11@11:34:46.816-0400] P-001156 T-016324 1 4GL LogMgrWrtr     [O.Net DEBUG] CHUNK: READ(b)= 55200
[17/04/11@11:34:46.819-0400] P-001156 T-016324 1 4GL LogMgrWrtr     [O.Net TRACE] CHUNK: FILE= temp\response-data-chunk-00312.txt
 
--->  [17/04/11@11:34:46.826-0400] P-001156 T-016324 1 4GL LogMgrWrtr     [O.Net DEBUG] ReadHandler:OnDataReceived time(ms)=17
 
[17/04/11@11:34:46.830-0400] P-001156 T-016324 1 4GL LogMgrWrtr     [O.Net DEBUG] ReadHandler: OK? yes
[17/04/11@11:34:46.833-0400] P-001156 T-016324 1 4GL LogMgrWrtr     [O.Net DEBUG] ReadHandler: time(ms)=3
[17/04/11@11:34:46.836-0400] P-001156 T-016324 1 4GL LogMgrWrtr     [O.Net DEBUG] ReadHandler: size(b)=38640
 
 
I would have suggested making a HEAD request to get the size of the response first and adjusting the receive buffer based on that but I found a bug in processing HEAD requests (PSC00356585)  
 
 
 
 

Posted by toomaskask on 12-Apr-2017 02:49

OK, I set both ReadBufferSize & ReceiveBufferSize to 32K.

[17/04/12@09:52:12.585+0300] P-012951 T-1483659040 1 4GL APPL Execute() start
[17/04/12@09:52:12.635+0300] P-012951 T-1483659040 1 4GL HTTPCLIB REQUEST: FILE= request-raw.txt
[17/04/12@09:52:12.636+0300] P-012951 T-1483659040 1 4GL HTTPCLIB RESPONSE: FILE= data-received.txt
[17/04/12@09:52:12.636+0300] P-012951 T-1483659040 1 4GL SOCKET CONNECT: -H xxx -S 8080
[17/04/12@09:52:12.639+0300] P-012951 T-1483659040 1 4GL SOCKET SO-RCVBUF: 65536
[17/04/12@09:52:12.639+0300] P-012951 T-1483659040 1 4GL SOCKET SO-RCVTIMEO: 30
[17/04/12@09:52:12.639+0300] P-012951 T-1483659040 1 4GL SOCKET CONNECT: TIME(ms)=2
[17/04/12@09:52:12.639+0300] P-012951 T-1483659040 1 4GL SOCKET WRITE: TIME(ms)=0
[17/04/12@09:52:12.639+0300] P-012951 T-1483659040 1 4GL SOCKET WRITE: SIZE(b)=182
[17/04/12@09:52:12.937+0300] P-012951 T-1483659040 1 4GL SOCKET READ: AVAIL(b)=14480
[17/04/12@09:52:12.937+0300] P-012951 T-1483659040 1 4GL SOCKET READ: TIME(ms)=0
[17/04/12@09:52:12.937+0300] P-012951 T-1483659040 1 4GL SOCKET READ: SIZE(b)=14480
[17/04/12@09:52:12.937+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: NUM= 1
[17/04/12@09:52:12.937+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: SIZE(b)= 32768
[17/04/12@09:52:12.937+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: READ(b)= 14480
[17/04/12@09:52:12.937+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: FILE= data-chunk-00001.txt
[17/04/12@09:52:13.009+0300] P-012951 T-1483659040 1 4GL SOCKET READ: AVAIL(b)=101360
[17/04/12@09:52:13.009+0300] P-012951 T-1483659040 1 4GL SOCKET READ: TIME(ms)=0
[17/04/12@09:52:13.009+0300] P-012951 T-1483659040 1 4GL SOCKET READ: SIZE(b)=32768
[17/04/12@09:52:13.009+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: NUM= 2
[17/04/12@09:52:13.009+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: SIZE(b)= 32768
[17/04/12@09:52:13.009+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: READ(b)= 32768
[17/04/12@09:52:13.009+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: FILE= data-chunk-00002.txt
...
...
...
[17/04/12@09:53:16.709+0300] P-012951 T-1483659040 1 4GL SOCKET READ: AVAIL(b)=44085
[17/04/12@09:53:16.710+0300] P-012951 T-1483659040 1 4GL SOCKET READ: TIME(ms)=0
[17/04/12@09:53:16.710+0300] P-012951 T-1483659040 1 4GL SOCKET READ: SIZE(b)=32768
[17/04/12@09:53:16.710+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: NUM= 632
[17/04/12@09:53:16.710+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: SIZE(b)= 32768
[17/04/12@09:53:16.710+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: READ(b)= 32768
[17/04/12@09:53:16.710+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: FILE= data-chunk-00632.txt
[17/04/12@09:53:17.012+0300] P-012951 T-1483659040 1 4GL SOCKET READ: AVAIL(b)=11317
[17/04/12@09:53:17.012+0300] P-012951 T-1483659040 1 4GL SOCKET READ: TIME(ms)=0
[17/04/12@09:53:17.012+0300] P-012951 T-1483659040 1 4GL SOCKET READ: SIZE(b)=11317
[17/04/12@09:53:17.013+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: NUM= 633
[17/04/12@09:53:17.013+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: SIZE(b)= 32768
[17/04/12@09:53:17.013+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: READ(b)= 11317
[17/04/12@09:53:17.013+0300] P-012951 T-1483659040 1 4GL HTTPCLIB CHUNK: FILE= data-chunk-00633.txt
[17/04/12@09:53:17.024+0300] P-012951 T-1483659040 1 4GL SOCKET READ: COMPLETE= yes
[17/04/12@09:53:17.024+0300] P-012951 T-1483659040 1 4GL SOCKET READ: ERROR= ?
[17/04/12@09:53:17.024+0300] P-012951 T-1483659040 1 4GL SOCKET READ: TOTAL TIME(ms)=64384
[17/04/12@09:53:17.024+0300] P-012951 T-1483659040 1 4GL SOCKET READ: TOTAL SIZE(b)=61273423
[17/04/12@09:54:16.015+0300] P-012951 T-1483659040 1 4GL APPL Execute() done

2min 2 sec total time, response size: 20 742 144 bytes.

Another question is why it takes 59sec to finish Execute after reading from network is done ? Merging chunks together?

[17/04/12@09:53:17.024+0300] P-012951 T-1483659040 1 4GL SOCKET READ: COMPLETE= yes
[17/04/12@09:53:17.024+0300] P-012951 T-1483659040 1 4GL SOCKET READ: ERROR= ?
[17/04/12@09:53:17.024+0300] P-012951 T-1483659040 1 4GL SOCKET READ: TOTAL TIME(ms)=64384
[17/04/12@09:53:17.024+0300] P-012951 T-1483659040 1 4GL SOCKET READ: TOTAL SIZE(b)=61 273 423 ???
[17/04/12@09:54:16.015+0300] P-012951 T-1483659040 1 4GL APPL Execute() done

EDIT: Another log file with 1MB buffer - same server, same url, same output:

1) Linux - https://pastebin.com/eGwe4USk - TIME(ms)=6805, TOTAL SIZE(b)=206 329 01, CHUNK: NUM= 217

2) Win64 - https://pastebin.com/StPSDHqt - TIME(ms)=990, TOTAL SIZE(b)=1 586 896, CHUNK: NUM= 25

Debug log seems a little bit weird to me. 

BR

Toomas

Posted by Peter Judge on 14-Apr-2017 09:16

This is 11.6.2, right? Is it HTTPS?
 
I would not expect to see the times being the same for both calls.
 

Posted by toomaskask on 17-Apr-2017 03:53

Hi,

Yes, 11.6.2. Plain HTTP connection.

Posted by Peter Judge on 11-May-2017 16:52

I know the URI is private (inside your firewall). What would be really helpful for me to be able to profile/discover at least some of the slowness would be the debug dump that's created when you enable logging

If you add

   log-manager:logfile-name = session:temp-dir + 'test_bigdata.log'.

   log-manager:logging-level = 6.

   log-manager:clear-log ().

to the beginning of your test code, the Http Client will crate a file called response-data-received.txt in your -T directory (along with a number of response-data-chunk-NNNN.txt files).

If you can email me the response-data-received file (or attach to this thread) it will be useful in trying to find the issue.

This thread is closed