Samba connection - how to troubleshoot what gets sent and received?

[Dariusz Piatkowski]

Guys!

I've had a pesky problem on my OS/2 box for a while now, that being on Samba connections Lucide takes far too long to open a PDF that's sitting out there on my NAS box. This is not just a Lucide issue, GSView as well as QPDFView show the same behaviour.

We are talking here PDF files that are about 70-150k in size that take 5-10 secs to open up.

To be clear, I am using NetDrive Samba plugin to make this work, and that could certainly be adding, I just can't tell.

What I can see is that as I open a PDF file my TCP/IP monitor shows multiple traffic spikes, they continue (back and forth) until the file is opened up. Now nearly each one of these are spikes are actually larger than the actual PDF file itself, so that's literally flooring me as I can't for the life of me understand what is causing the traffic to happen.

Alright...so how can I troubleshoot this in order to figure out what all that "overhead" is that appears to be moving back and forth?

I've got Wireshark installed, so I could capture the packets as the transactions start...but is there something a little more human-digestable? I'm thinking Samba logging perhaps?

Thanks!

[Paul Smedley]

Hi Dariusz,

I've had a pesky problem on my OS/2 box for a while now, that being on Samba connections Lucide takes far too long to open a PDF that's sitting out there on my NAS box. This is not just a Lucide issue, GSView as well as QPDFView show the same behaviour.

We are talking here PDF files that are about 70-150k in size that take 5-10 secs to open up.

To be clear, I am using NetDrive Samba plugin to make this work, and that could certainly be adding, I just can't tell.

What I can see is that as I open a PDF file my TCP/IP monitor shows multiple traffic spikes, they continue (back and forth) until the file is opened up. Now nearly each one of these are spikes are actually larger than the actual PDF file itself, so that's literally flooring me as I can't for the life of me understand what is causing the traffic to happen.

Alright...so how can I troubleshoot this in order to figure out what all that "overhead" is that appears to be moving back and forth?

I've got Wireshark installed, so I could capture the packets as the transactions start...but is there something a little more human-digestable? I'm thinking Samba logging perhaps?

Samba logs please. Create a file \ndpsmb.dbg on the drive where ndpsmb.dll is installed. Run your test, then send me \var\log\log.ndpsmb

[Mike Kölling]

Hi Darius,

kindly try to disable the "Supports EA" flag when you mount the share of your NAS. That helped me in a similar case.

Greetings from Potsdam, Germany.
Mike

[Paul Smedley]

Hi Mike,

kindly try to disable the "Supports EA" flag when you mount the share of your NAS. That helped me in a similar case.

I forget now if you sent me logs about this,  but it would be nice to NOT have to disable the supports EA flag, and handle this more gracefully in the plugin.

Cheers,

Paul

[Dariusz Piatkowski]

Hi Mike!

Hi Darius,

kindly try to disable the "Supports EA" flag when you mount the share of your NAS. That helped me in a similar case.

Greetings from Potsdam, Germany.
Mike

The NAS box does not support EAs, so I have that disabled in my NetDrive share configuration.

I remember trying to troubleshoot this a while back...I think I captured the LOGs that Paul is talking about and it looked like the PDFs were getting transfered in tiny chunks, we are talking here like 2-3K, while other objects (such as JPEGs for example) would max out at about 32K.

OK, yeah, I saved that old debug log and here is what I found:

1) JPEGs

Code: [Select]

...
NdpQueryPathInfo <public\DOCUMENTS\Family\Finance\TAX\2016\US Info\2016 - MI - Tax Refund Statement.jpg> () 0
2020/06/11 16:18:53.50: 9 2: smbopen in [0x6e3a80] -1
2020/06/11 16:18:53.50: 4 2: cli_open(\public\DOCUMENTS\Family\Finance\TAX\2016\US Info\2016 - MI - Tax Refund Statement.jpg) attr 00000000 mode 100 denymode 04
2020/06/11 16:18:53.51: 9 2: smbopen <public\DOCUMENTS\Family\Finance\TAX\2016\US Info\2016 - MI - Tax Refund Statement.jpg> (\public\DOCUMENTS\Family\Finance\TAX\2016\US Info\2016 - MI - Tax Refund Statement.jpg) 00000100 08000040 00000000 0. file = 17556
2020/06/11 16:18:53.51: 9 2: NdpFileQueryInfo in [0x6e3a80]
2020/06/11 16:18:53.51: 9 2: fname \public\DOCUMENTS\Family\Finance\TAX\2016\US Info\2016 - MI - Tax Refund Statement.jpg
2020/06/11 16:18:53.51: 9 2: btime 1494688532 Sat May 13 11:15:32 2017
2020/06/11 16:18:53.51: 9 2: atime 1591275626 Thu Jun  4 09:00:26 2020
2020/06/11 16:18:53.51: 9 2: mtime 1494688532 Sat May 13 11:15:32 2017
2020/06/11 16:18:53.51: 9 2: ctime 1494688532 Sat May 13 11:15:32 2017
2020/06/11 16:18:53.51: 9 2: ftimeLastAccess 11:15:32
2020/06/11 16:18:53.51: 9 2: NdpFileQueryInfo <\public\DOCUMENTS\Family\Finance\TAX\2016\US Info\2016 - MI - Tax Refund Statement.jpg> 0
2020/06/11 16:18:53.51: 9 2: NdpFileSetFilePtrL in [0x6e3a80]
2020/06/11 16:18:53.51: 4 2: lseek 1 0 0
2020/06/11 16:18:53.51: 9 2: NdpFileSetFilePtrL <\public\DOCUMENTS\Family\Finance\TAX\2016\US Info\2016 - MI - Tax Refund Statement.jpg> 0 1 0 0
2020/06/11 16:18:53.51: 9 2: NdpFileQueryInfo in [0x6e3a80]
2020/06/11 16:18:53.51: 9 2: fname \public\DOCUMENTS\Family\Finance\TAX\2016\US Info\2016 - MI - Tax Refund Statement.jpg
2020/06/11 16:18:53.51: 9 2: btime 1494688532 Sat May 13 11:15:32 2017
2020/06/11 16:18:53.51: 9 2: atime 1591275626 Thu Jun  4 09:00:26 2020
2020/06/11 16:18:53.51: 9 2: mtime 1494688532 Sat May 13 11:15:32 2017
2020/06/11 16:18:53.51: 9 2: ctime 1494688532 Sat May 13 11:15:32 2017
2020/06/11 16:18:53.51: 9 2: ftimeLastAccess 11:15:32
2020/06/11 16:18:53.51: 9 2: NdpFileQueryInfo <\public\DOCUMENTS\Family\Finance\TAX\2016\US Info\2016 - MI - Tax Refund Statement.jpg> 0
2020/06/11 16:18:53.51: 9 2: NdpFileRead in [0x6e3a80], ulRead = 32768
2020/06/11 16:18:53.52: 4 2:  smbwrp_read successful, nread = 32768, ret = 0
...

2) PDFs

Code: [Select]

...
NdpQueryPathInfo <PUBLIC\DOCUMENTS\Family\FINANCE\TAX\2016\US Info\2016 - MTOR - Paystub - FINAL.pdf> (\PUBLIC\DOCUMENTS\Family\FINANCE\TAX\2016\US Info\2016 - MTOR - Paystub - FINAL.pdf) 0
2020/06/11 20:53:17.76: 9 2: smbopen in [0x6fb340] -1
2020/06/11 20:53:17.76: 4 2: cli_open(\PUBLIC\DOCUMENTS\Family\FINANCE\TAX\2016\US Info\2016 - MTOR - Paystub - FINAL.pdf) attr 00000000 mode 100 denymode 04
2020/06/11 20:53:17.76: 9 2: smbopen <PUBLIC\DOCUMENTS\Family\FINANCE\TAX\2016\US Info\2016 - MTOR - Paystub - FINAL.pdf> (\PUBLIC\DOCUMENTS\Family\FINANCE\TAX\2016\US Info\2016 - MTOR - Paystub - FINAL.pdf) 00000100 08000040 00000000 0. file = 17563
2020/06/11 20:53:17.76: 9 2: NdpRsrcQueryInfo in
2020/06/11 20:53:17.76: 9 2: NdpRsrcQueryInfo 0
2020/06/11 20:53:17.76: 9 2: NdpFileSetFilePtrL in [0x6fb340]
2020/06/11 20:53:17.76: 4 2: lseek 2 0 0
2020/06/11 20:53:17.76: 9 2: NdpFileSetFilePtrL <\PUBLIC\DOCUMENTS\Family\FINANCE\TAX\2016\US Info\2016 - MTOR - Paystub - FINAL.pdf> 0 2 4322 0
2020/06/11 20:53:17.76: 9 2: NdpFileSetFilePtrL in [0x6fb340]
2020/06/11 20:53:17.76: 4 2: lseek 2 0 4322
...

I'll get a NEW log built because that was way back in 2020 (June) and I'm pretty sure we've had Samba client updates since.

[Paul Smedley]

I'll get a NEW log built because that was way back in 2020 (June) and I'm pretty sure we've had Samba client updates since.

Please use https://smedley.id.au/tmp/ndpsmb-3.7.3-samba411-20220108.zip if possible

Cheers,

Paul

[Dariusz Piatkowski]

Hi Paul,

Please use https://smedley.id.au/tmp/ndpsmb-3.7.3-samba411-20220108.zip if possible

Alright, I grabbed that plugin, deployed and tested with three test-cases:

1) JPEG
regular JEPG image, see log.ndpsmb.JPEG

2) PDF - Large file
PDF file, this one is about 5.6M is size, see log.ndpsmb.PDF_large

3) PDF - Small file
PDF file, this one is about 175K in size, see log.ndpsmb.PDF_small

Each test-case was re-started from scratch, meaning: NDCTL re-start each time, which produced a clean log.ndpsmb file, so the log files you see above contain JUST the information pertinent to that single test-case.

Otherwise, I have my share configured to do:

1) Cache Timeout of 10 sec (default)
2) Cache Lsting of 80 (as opposed to the default of 32 I think - this appears to have made my NAS connectivity mroe stable, at least as far as WPS file operations go)

I have tried multiple configurations here of the above values in hopes of figuring out if one of these settings causes a too-frequent cache refresh, which in turn kills the performance, but I haven't found anything here. Either way, the other file types do not appear to be impacted, just the PDFs.

See attached ZIP file, let me know if you want me to send it anywhere else?

Thank You!

[Paul Smedley]

Thanks  - will look when I get a moment. re: the cache- that only caches directory listings, not files, so should have no bearing on read/write performance.

[Paul Smedley]

Can you please confirm the versions of Lucide issue, GSView as and QPDFView that are in use? Poppler may be a common theme here.

[Dariusz Piatkowski]

Can you please confirm the versions of Lucide issue, GSView as and QPDFView that are in use? Poppler may be a common theme here.

1) Lucide - 1.5.0 GA (2019-03-20)
- lupplr PDF plugin, based on poppler library 0.59.0

2) GSView - 5.0 (2012-01-17)

3) QPDFView - 0.4.17.beta2
- PDF support using Poppler 0.52.0

Here is the Poppler installed RPM package info:

poppler.pentium4                        0.90.1-1.oc00
poppler-cpp.pentium4                  0.90.1-1.oc00
poppler-data.noarch                     0.4.9-1.oc00
poppler-legacy-65.pentium4          0.49.0-2.oc00.L
poppler-legacy-66.pentium4          0.52.0-1.oc00.L
poppler-legacy-70.pentium4          0.59.0-3.oc00.L
poppler-legacy-72.pentium4          0.61.1-1.oc00.L
poppler-legacy-94.pentium4          0.84.0-1.oc00.L
poppler-qt.pentium4                     0.90.1-1.oc00
poppler-utils.pentium4                  0.90.1-1.oc00

[Paul Smedley]

In the case of GSView, it is the ghostscript version that's important. Are you able to confirm the ghostscript version, and if it uses Poppler?

[Dariusz Piatkowski]

Paul,

In the case of GSView, it is the ghostscript version that's important. Are you able to confirm the ghostscript version, and if it uses Poppler?

I am using GScript 9.04 here...so I suspect this is not using poppler in any way.