ncat transfer rate incredibly slow

[Vhati]

I first noticed incredibly slow rates across my LAN a while back, but lazily switched tools and forgot about the bug - assuming it'd be obvious and get fixed eventually. Oops.

I finally decided to run some loopback tests to report it properly.

ncat -l --recv-only 5000 > out.bin
ncat --send-only 127.0.0.1 5000 < in.bin

Transfer times (via a wristwatch) on Windows 7, for an arbitrary a 9MB file, with matching versions of ncat.
6.40 sending to 6.40 - Instantaneous
6.45 sending to 6.45 - Four minutes!
Every released version thereafter* (until 7.50) is also slow.

If I mix versions to tease apart whether sending or receiving is the bottleneck...
6.40 sending to 6.45 - Instantaneous
6.45 sending to 6.40 - Four minutes
So 6.45 can receive quickly, but it is slow to send.

• 7.60 was not tested due to issue ncat: nsock_loop error 10038 #978

[Vhati]

Mixed test for the latest working release.
6.40 sending to 7.50 - Instantaneous
7.50 sending to 6.40 - Four minutes
Same problem, slow to send.

[dmiller-nmap]

possibly related #1025

[dmiller-nmap]

It sounds like it only affects the client/connect code, not the server/listen code, right? Can you try running the transfer in the opposite direction and let us know the times when 7.50 is the client and when 6.40 is the client? Example:

ncat -l --send-only 5000 < in.bin
ncat --recv-only 127.0.0.1 5000 > out.bin

I'm going to try it here on Linux and see if I get similar results.

[dmiller-nmap]

Current ncat on Linux does not have this issue with localhost. Have not tested over the network yet.

@hdoreau The only change in the Changelog between 6.40 and 6.45 that might affect this is r31737 (853aaff), Manage expiration timers via a heap queue. Can you think of any reason this would have bad performance on Windows?

[Vhati]

Can you try running the transfer in the opposite direction and let us know the times

ncat750 -l --send-only 5000 < in.bin
ncat640 --recv-only 127.0.0.1 5000 > out.bin
Four minutes

ncat640 -l --send-only 5000 < in.bin
ncat750 --recv-only 127.0.0.1 5000 > out.bin
Instantaneous

[Vhati]

Unless I'm mixed up, I think 7.50 is just slow sending, regardless of whether it connected/listened.

[Vhati]

I tried piping an endless stream.
python -c "while(True): print 'z'" | ncat750 -l --send-only 5000
ncat640 --recv-only 127.0.0.1 5000 > out.bin
Slow
(spot checked growth of out.bin, ex: being 64k after a second)

Whether it's a filesystem redirect or a pipe, sending is still slow.

[hdoreau]

Hello, I cannot think of anything in the switch from lists to heap in timer management that would cause such a slowdown, esp. since the problem appears to be windows-specific.

I have no windows machine to test on. Vhati, can you reproduce both normal & slow cases with nsock logging level set to the maximum? I believe this may help...

[Vhati]

@hdoreau

can you reproduce both normal & slow cases with nsock logging level set to the maximum?

I wasn't sure what you meant, so I used ncat's -vvvv arg.
Logs are zipped and attached below.

Create a 256 KB file.
Still noticably slow at 7 seconds but less log spam.

python -c "print 'z' * (1024*256)" > in.bin

Test 01 (Transfer from 6.40 to 6.40, sender connects, fast):

ncat640 -vvvv -l --recv-only 5000 > out.bin 2>test_01-listen.txt

ncat640 -vvvv --send-only 127.0.0.1 5000 < in.bin 2>test_01-connect.txt

Test 02 (Transfer from 7.50 to 7.50, sender connects, slow):

ncat750 -vvvv -l --recv-only 5000 > out.bin 2>test_02-listen.txt

ncat750 -vvvv --send-only 127.0.0.1 5000 < in.bin 2>test_02-connect.txt

Test 03 (Transfer from 6.40 to 7.50, sender connects, fast):

ncat750 -vvvv -l --recv-only 5000 > out.bin 2>test_03-listen.txt

ncat640 -vvvv --send-only 127.0.0.1 5000 < in.bin 2>test_03-connect.txt

Test 04 (Transfer from 6.40 to 7.50, sender listens, fast):

ncat640 -vvvv -l --send-only 5000 < in.bin 2>test_04-listen.txt

ncat750 -vvvv --recv-only 127.0.0.1 5000 > out.bin 2>test_04-connect.txt

Test 05 (Transfer from 7.50 to 6.40, sender listens, slow):

ncat750 -vvvv -l --send-only 5000 < in.bin 2>test_05-listen.txt

ncat640 -vvvv --recv-only 127.0.0.1 5000 > out.bin 2>test_05-connect.txt

Summary for comparison...
7.50 slow as listening-receiver in test 02.
7.50 fast as listening-receiver in test 03.
7.50 fast as connecting-receiver in test 04.

7.50 was slow as connecting-sender in test 02.
7.50 was slow as listening-sender in test 05.
7.50 didn't have any fast sender log to compare.

ncat_issue_1026_transfer_rate_tests.zip

[hdoreau]

thanks, I would need exactly this but with -vvvvvvv (that's 7 v's) instead so as to get as much information as possible from nsock.

[Vhati]

@hdoreau

I would need exactly this but with -vvvvvvv (that's 7 v's) instead

Ha! Okay, here ya go.

ncat_issue_1026_transfer_rate_tests_verbose.zip

[dmiller-nmap]

My first observation is that timeouts are reported in an odd way. Note that the READ events have very odd timeout values:

libnsock nsock_pool_add_event(): NSE #18: Adding event (timeout in 327100488ms)

This is because in event_new, if the timeout passed in is -1, then the event's timeout is not changed from 0. The nsock_pool_add_event and process_event functions simply subtract the current time from the timeout time. On Linux, this ends up with a large negative value; I'm not sure why it's positive on Windows. The actual timeout check in event_timedout checks for a 0 timeout, so everything works fine, but the debug output is wrong.

Sorry for the distraction, but I hadn't found anything relevant to the transfer speed yet.

[Vhati]

ncat 7.70 is affected.
No new info to report. Just confirming the bug hasn't gone away.

I subjected the current version to Test 02. Same OS, same payload.
(Transfer from 7.70 to 7.70, sender connects, slow)

Ncat: 262146 bytes sent, 0 bytes received in 7.36 seconds.

Logs look the same, including having weirdly huge timeouts, through the timeout values varied (29672103ms).