JCIFS is slow, extremely slow

[3c71]

I used to run the old jcifs implementation, limited to SMB1 and hoped that upgrading to jcifs-ng and SMB2/3 will help with performance. Picked jcifs-ng because it's 100% compatible with old implementation and didn't require me to change much.

However it doesn't help in terms of performance, not a single bit.

On the same WiFi network, using the same NAS and the same Android app, FTP file-copy goes to 45MB/s while jcifs(-ng) is limited to 4.5MB/s, that's a tenth of the actual bandwidth!

I verified in logs that SMB2 messages where used. So protocol version does not help in any ways. Maybe SMB3 could?

Any insight or help would be much appreciated.

[mbechler]

SMB (no matter the version) throughput mostly depends on read/write buffer sizes. The smaller these are the more overhead you have and the more network latency matters (time spend sending the small read-request/write-response). 4.5 MB/s seems quite low, so I guess your usage pattern might not allow optimal usage, you need to check that you pass a sufficently large buffer into your read/write calls (around 64kb should be optimal).

[3c71]

Buffers are set to 65Kb, otherwise using default size gets to half of that throughput.

The usage pattern is strictly identical to the FTP tests, it's just 2 input streams, one using FTP, the other SMB. And I can't see overhead causing a 90% bandwidth reduction anyway.

I tested ES Explorer from Play Store, exactly the same results, 4.5MB/s. However from a Windows desktop I get those 45-50MB/s bandwidth as expected.

[mbechler]

I would suggest having a look at a network trace to see what kind of buffer sizes you actually get.

[3c71]

Good idea, I'll install wireshark to see what's actually going on. Do you get good bandwidth using SMB?

[mbechler]

I''m able to get up to 50 MB/s locally. If signing is active that might also cause some slow-down, especially on less powerful devices.

[3c71]

Do you use that library on Android?

I would think the S9 is a less powerful devices, and it's irrelevant as it can run FTP @ 50MB/s.

I logged all traffic and all I could see is nothing during the copy, big packets are being transmitted, no errors, no particular message.

Only thing I noticed is before the copy (when connecting or so) it showed a few 'not_defined_in_RFC4178@please_ignore'.

Do you use any particular settings? I'm using laster master, with default settings or with those, same results:

    System.setProperty("jcifs.smb.client.snd_buf_size", String.valueOf(65 * 1024));  // Tried 1024 * 1024
    System.setProperty("jcifs.smb.client.rcv_buf_size", String.valueOf(65 * 1024));

    System.setProperty("jcifs.util.loglevel", "3");

    System.setProperty("jcifs.smb.client.disableSMB1", "true");
    System.setProperty("jcifs.smb.client.enableSMB2", "true");
    System.setProperty("jcifs.resolveOrder", "DNS");
    System.setProperty("jcifs.smb.client.useExtendedSecurity", String.valueOf(false) );
    System.setProperty("jcifs.smb.client.dfs.disabled", String.valueOf(false) );  // tried true

Any other settings that could help?

Thanks by the way for replying ;)

[3c71]

Looking into more details about the traffic during copy (from NAS to Android), I see 9 'packets' then a single kind-of reply, then another 9 packets, and this seems to repeat itself, then I saw more than 10 packets... Hard to tell on a small device ;)

Packets appear to be of various sizes, can't tell exactly as the app I'm using is not very detailed on that.

The first packet always starts with ???SMB@! 33f??? ... then X packets, then a reply and it loops.

I don't see anything slowing down the process, but I suspect it's inherent to Android, there must be something configured differently???

[3c71]

In Android logs (once activated) I see such messages, repeating themselves during a file copy:

2018-09-15 14:41:08.606 13661-14027/ccc71.at:ui V/android_tuner:SmbTrans: Sending command=SMB2_READ,status=0,flags=0x0000,mid=0,wordCount=0,byteCount=0 2018-09-15 14:41:08.607 13661-14027/ccc71.at:ui V/android_tuner:SmbTrans: command=SMB2_READ,status=0,flags=0x0000,mid=884,wordCount=0,byteCount=49 2018-09-15 14:41:08.607 13661-14027/ccc71.at:ui V/android_tuner:SmbTrans: FE534D424000000000000000080001000800000000000000740300000000000000000000B93340DDB2BAD3E4000000001D586240F589C20D7F55404B45E2271531000000A8FD0000F0CA9F02000000003D89D6FC000000008E8AB4F900000000000000000000000068100900000000000000000000000000 2018-09-15 14:41:08.615 13661-14134/ccc71.at:ui V/android_tuner:SmbTrans: New data read: Transport0[e3c-nas/71.25.9.157:445,state=3,signingEnforced=false,usage=3] 2018-09-15 14:41:08.618 13661-14134/ccc71.at:ui V/android_tuner:SmbTrans: FE534D4240000000000000000800010009000000000000007403000000000000 2018-09-15 14:41:08.619 13661-14027/ccc71.at:ui V/android_tuner:SmbTrans: Adding credits 1 2018-09-15 14:41:08.619 13661-14027/ccc71.at:ui V/android_tuner:SmbTrans: Response is command=SMB2_READ,status=0,flags=0x0009,mid=884,wordCount=0,byteCount=0 2018-09-15 14:41:08.619 13661-14027/ccc71.at:ui V/android_tuner:SmbSessi: Response command=SMB2_READ,status=0,flags=0x0009,mid=884,wordCount=0,byteCount=0 2018-09-15 14:41:08.619 13661-14027/ccc71.at:ui V/android_tuner:Transport: Release transport 2 Transport0[e3c-nas/71.25.9.157:445,state=3,signingEnforced=false,usage=2] 2018-09-15 14:41:08.619 13661-14027/ccc71.at:ui V/android_tuner:Transport: Release transport 1 Transport0[e3c-nas/71.25.9.157:445,state=3,signingEnforced=false,usage=1] 2018-09-15 14:41:08.619 13661-14027/ccc71.at:ui V/android_tuner:SmbSessi: Release session 1 SmbSession[credentials=admin,targetHost=e3c-nas,targetDomain=null,uid=0,connectionState=2,usage=1] 2018-09-15 14:41:08.619 13661-14027/ccc71.at:ui V/android_tuner:SmbTreeI: Release tree 2 SmbTree[share=MEDIAS,service=null,tid=-582995015,inDfs=false,inDomainDfs=false,connectionState=2,usage=2] 2018-09-15 14:41:08.619 13661-14027/ccc71.at:ui V/android_tuner:SmbFileI: read: len=594024,r=64936,fp=44091544,b.length=1048576 2018-09-15 14:41:08.619 13661-14027/ccc71.at:ui V/android_tuner:SmbSessi: Acquire session 2 SmbSession[credentials=admin,targetHost=e3c-nas,targetDomain=null,uid=0,connectionState=2,usage=2] 2018-09-15 14:41:08.619 13661-14027/ccc71.at:ui V/android_tuner:Transport: Acquire transport 2 Transport0[e3c-nas/71.25.9.157:445,state=3,signingEnforced=false,usage=2] 2018-09-15 14:41:08.620 13661-14027/ccc71.at:ui V/android_tuner:Transport: Release transport 1 Transport0[e3c-nas/71.25.9.157:445,state=3,signingEnforced=false,usage=1] 2018-09-15 14:41:08.620 13661-14027/ccc71.at:ui V/android_tuner:SmbSessi: Release session 1 SmbSession[credentials=admin,targetHost=e3c-nas,targetDomain=null,uid=0,connectionState=2,usage=1] 2018-09-15 14:41:08.620 13661-14027/ccc71.at:ui V/android_tuner:SmbTreeI: Acquire tree 3 SmbTree[share=MEDIAS,service=null,tid=-582995015,inDfs=false,inDomainDfs=false,connectionState=2,usage=3] 2018-09-15 14:41:08.620 13661-14027/ccc71.at:ui V/android_tuner:SmbSessi: Acquire session 2 SmbSession[credentials=admin,targetHost=e3c-nas,targetDomain=null,uid=0,connectionState=2,usage=2] 2018-09-15 14:41:08.620 13661-14027/ccc71.at:ui V/android_tuner:Transport: Acquire transport 2 Transport0[e3c-nas/71.25.9.157:445,state=3,signingEnforced=false,usage=2] 2018-09-15 14:41:08.620 13661-14027/ccc71.at:ui V/android_tuner:SmbSessi: Acquire session 3 SmbSession[credentials=admin,targetHost=e3c-nas,targetDomain=null,uid=0,connectionState=2,usage=3] 2018-09-15 14:41:08.620 13661-14027/ccc71.at:ui V/android_tuner:Transport: Acquire transport 3 Transport0[e3c-nas/71.25.9.157:445,state=3,signingEnforced=false,usage=3] 2018-09-15 14:41:08.620 13661-14027/ccc71.at:ui V/android_tuner:Transport: Release transport 2 Transport0[e3c-nas/71.25.9.157:445,state=3,signingEnforced=false,usage=2] 2018-09-15 14:41:08.620 13661-14027/ccc71.at:ui V/android_tuner:SmbSessi: Release session 2 SmbSession[credentials=admin,targetHost=e3c-nas,targetDomain=null,uid=0,connectionState=2,usage=2] 2018-09-15 14:41:08.620 13661-14027/ccc71.at:ui V/android_tuner:Transport: Acquire transport 3 Transport0[e3c-nas/71.25.9.157:445,state=3,signingEnforced=false,usage=3] 2018-09-15 14:41:08.620 13661-14027/ccc71.at:ui V/android_tuner:Transport: Acquire transport 4 Transport0[e3c-nas/71.25.9.157:445,state=3,signingEnforced=false,usage=4] 2018-09-15 14:41:08.621 13661-14027/ccc71.at:ui V/android_tuner:Transport: Release transport 3 Transport0[e3c-nas/71.25.9.157:445,state=3,signingEnforced=false,usage=3] 2018-09-15 14:41:08.621 13661-14027/ccc71.at:ui V/android_tuner:SmbSessi: Request command=SMB2_READ,status=0,flags=0x0000,mid=0,wordCount=0,byteCount=0 2018-09-15 14:41:08.622 13661-14027/ccc71.at:ui V/android_tuner:SmbTrans: Sending command=SMB2_READ,status=0,flags=0x0000,mid=0,wordCount=0,byteCount=0 2018-09-15 14:41:08.622 13661-14027/ccc71.at:ui V/android_tuner:SmbTrans: jcifs.internal.smb2.io.Smb2ReadRequest costs 1 avail 512 (Transport0) 2018-09-15 14:41:08.622 13661-14027/ccc71.at:ui V/android_tuner:SmbTrans*: Request credits 1

Is that expected that it release/acquire transports/sessions continually?

Actually when I see r=64936 and that it took 16ms to process, it's close to 4MB/s ! The throughput I actually see.

The b.length = 1MB is due to a 1MB buffer used to copy for testing. Using 64K buffer makes not difference.

Furthermore, between the READ command and the new data read, there's about 9ms, that's an overhead of 7ms in various handling. Still 9ms is way too much to achieve 50MB/s.

What are those credits for? Could I request more to read in parallel ?

[3c71]

Just started testing another Samba implementation (https://github.com/3c71/smbj), and immediately got 7MB/sec.

Very far from available bandwidth. And it's not a local test, the server is in another room accessible over WiFi.

[mbechler]

I haven't used the library on android.

14:41:08.607 is directly before the socket write and 14:41:08.615 is the socket read returning data, so everything in between there is outside of the library (network stack, network, server). So there is definitely (also) something else preventing you from getting reasonable performance. For figuring out what the overhead is using a profiler (if there is one for android) would be good. The release/acquires look normal to me, as long as the synchronization primitives aren't extremely bad on android these should not be an issue. One thing I could imagine might be an issue is logging, I'm not sure about the logger implementation on android, maybe you can replace it with the nop backend for a test. There are some new benchmarks in #106 which also show much higher throughput than you are getting, these also indicate that smbj might be a bit faster as you found too.

Credits are the SMB mechanism to restrict request parallelism, so yes, in therory you could do requests in parallel, but you would have to do the read/writes yourself, SmbFileInput/OutputStream does not handle that.

[3c71]

That's precisely 8ms to get a 64K buffer, which give a max throughput of 8MB/s, compared to actual network bandwidth, that's pretty low. Add to that some further latency/handling and this drops to 4MB/s. There's no way to achieve 50MB/s using SMB 1 or 2, except with a latency below 1ms AND a network bandwidth of 100MB/s or so.

Not something you get on a WiFi network, so I'll never get higher throughput with SMB. :(

[jansohn]

I can confirm that my benchmarks were performed on a wired 1000Mbps connection with very low latency. Ping utility on Windows shows time<1ms.

[tubeuchiha]

I used to run the old jcifs implementation, limited to SMB1 and hoped that upgrading to jcifs-ng and SMB2/3 will help with performance. Picked jcifs-ng because it's 100% compatible with old implementation and didn't require me to change much.

However it doesn't help in terms of performance, not a single bit.

On the same WiFi network, using the same NAS and the same Android app, FTP file-copy goes to 45MB/s while jcifs(-ng) is limited to 4.5MB/s, that's a tenth of the actual bandwidth!

I verified in logs that SMB2 messages where used. So protocol version does not help in any ways. Maybe SMB3 could?

Any insight or help would be much appreciated.

on adnroid ,How do you solve this problem after ?

[mbechler]

SMB3 should not change anything in that regard, what probably would is if we implemented multi credit support. With regards to android specifically, maybe someone can do some profiling and see whether there is something in the code that causes a significant slowdown there.