Weird behaviour for PDF viewer - during network access only

[Dariusz Piatkowski]

So I've been toying with the idea of moving all of my local (OS/2) docs to the LAN NAS. The NAS has about 8TB space, gets backed up every night while the OS/2 box has a live nightly backup but only to an internal HD. Yes, I know I could probably use the rsync job to push stuff from the OS/2 box to the NAS/Backup but given that I want these docs to be accessible from all the other home devices it just seems like NAS is the ideal storage place.

Anyways, my "Documents" folder is about 2 Gig of data, some 12k files. I executed a copy to the NAS, WPS copy failed, but Larsen Commander came through - I suspect the EAs were a problem for WPS since my NAS does not support them, just a guess, I haven't debugged it further.

Once on the NAS I proceeded to test access, basicaly standard "find the file, open through WPS associations", etc, etc.

All good until I hit my PDFs. So I've got three PDF readers installed here: Lucide, GSView 5.0, and QPDFView. Both Lucide and QPDFView exhibit this weird behaviour: all PDF loading is extremely slow, I can actualy see chunks of 64K being received and sent over my TCP/IP monitor, this continues until the 1st page is rendered and repeats when succeeding pages are loaded. GSView on the other hand just chomps away magnitudes faster, so any big PDFs just show up as a big spike on the monitor. On the LAN it is very quick.

Sometimes the Lucide/QPDFView "load chunks" get larger, it seems to depend on how big of a PDF I'm actually openning. The bigger file - 38M in size - caused the chunks to increase to about 700K on the receive and a matching 200k on the send.

So here is the thing, Lucide is my default viewer. Given that both it and QPDFView exhibit the same behaviour I'm thinking it is something with poppler?

Therefore, I'm curious if anyone else has experienced something similar?

What could I do to try to debug this further?

Right now it is just about the only thing preventing me from moving to the NAS.

[Paul Smedley]

Hey there, I'd be interested in some Samba logs from this, just to see if there's something unusual happening within the Netdrive plugin - I'm assuming this is with the Samba 4.x plugin?

[Dariusz Piatkowski]

Hey Paul,

Hey there, I'd be interested in some Samba logs from this, just to see if there's something unusual happening within the Netdrive plugin - I'm assuming this is with the Samba 4.x plugin?

Yeah, this is with the latest 4.9.5 drop, I haven't tried with the test 4.10.0 release yet, however given that the difference is seen between different PDF viewers I'm thinking it may not be Samba client related? For what it's worth the behaviour is the same regardless of whether I'm reading the file from the NAS or the Win7Pro box.

Anyways, toss some instructions at me to grab some logs, unless the standard log from the NetDrive interface will suffice? I'm thinking the one which get started by tossing ndpsmb.dbg into the root of the boot drive...

[xynixme]

FWIW: here QPDFView still doesn't work (no support for PDF file format), and Lucide appends lines to POPUPLOG.OS2 when the number of times it's being executed is an odd number.

[David Graser]

FWIW: here QPDFView still doesn't work (no support for PDF file format), and Lucide appends lines to POPUPLOG.OS2 when the number of times it's being executed is an odd number.

What version of Lucide are you using?

[Paul Smedley]

Hi Dariusz,

Hey there, I'd be interested in some Samba logs from this, just to see if there's something unusual happening within the Netdrive plugin - I'm assuming this is with the Samba 4.x plugin?

Yeah, this is with the latest 4.9.5 drop, I haven't tried with the test 4.10.0 release yet, however given that the difference is seen between different PDF viewers I'm thinking it may not be Samba client related? For what it's worth the behaviour is the same regardless of whether I'm reading the file from the NAS or the Win7Pro box.

Anyways, toss some instructions at me to grab some logs, unless the standard log from the NetDrive interface will suffice? I'm thinking the one which get started by tossing ndpsmb.dbg into the root of the boot drive...

Yes, just the ndpsmb.log that's creating from placing ndpsmb.dbg in the root of the boot drive will suffice.

[Dariusz Piatkowski]

Hi David,

What version of Lucide are you using?

I've got 1.41 RC_4 (2019_01_08), which I believe is the last test release that Gregg did. Not sure if that has gone to a final release.

[Dariusz Piatkowski]

Hi Paul,

Yes, just the ndpsmb.log that's creating from placing ndpsmb.dbg in the root of the boot drive will suffice.

Alright, so I've attached a ZIP file of two runs (separate LOGs):

1) PDF file - log.ndpsmb.test_1_pdf
2) JPG file - log.ndpsmb.test_2_image

Now, looking at these from here I pick up one major difference, the image file is showing a good chunk of successfull file read as follows:

Code: [Select]

2019/04/21 21:32:53.18: 9 2: NdpFileRead <\public\test_image.jpg> 32768 32768 0
2019/04/21 21:32:53.20: 9 2: NdpFileRead in [0x703b20], ulRead = 32768
2019/04/21 21:32:53.20: 4 2:  smbwrp_read successful, nread = 32768, ret = 0

So it looks like 32K blocks each read and subsequently my IP trafic monitor shows a pretty steady 3-4Mb read for a split second, file loads pretty quickly.

In the meantime the PDF file shows a lot of this stuff:

Code: [Select]

2019/04/21 21:12:15.95: 4 2: lseek 0 2002 1917337
2019/04/21 21:12:15.95: 9 2: NdpFileSetFilePtrL <\PUBLIC\Garage - Wayne Dalton 9602 - 9100_9600_Brochure_2.10.pdf> 2002 0 2002 0
2019/04/21 21:12:15.95: 9 2: NdpFileRead in [0x703b20], ulRead = 256
2019/04/21 21:12:15.96: 4 2:  smbwrp_read successful, nread = 256, ret = 0

...which implies that each read is literally all of 256 bytes...some are even smaller, I see stuff that's occasionally as small as 37 bytes.

Can you tell why this is happening? Maybe there is a setting in my smb.conf that's causing a problem?

[Paul Smedley]

Hi Dariusz,

Can you tell why this is happening? Maybe there is a setting in my smb.conf that's causing a problem?

The bytes to read is passed from the app to Netdrive, see http://trac.netlabs.org/samba/browser/branches/client-3.0/src/ndpsmb.c#L2243

I'm guess an issue in poppler?

Cheers,

Paul

[ivan]

Hi Dariusz,

Have you tried backleveling lucide to 1.3.5GA (2012-09-13) to see if that changes anything?

I have had problems with most versions beyond that one and since it reads all the PDFs I want I standardised on that version (yes it reads PDFs from my NAS boxes (DNS323 & DNS 320) without problems).

OT and out of curiosity what TCP/IP monitor are you using? The one I have always used stopped working when I upgraded to ArcaOS.

[Dariusz Piatkowski]

Hi Paul,

...The bytes to read is passed from the app to Netdrive, see http://trac.netlabs.org/samba/browser/branches/client-3.0/src/ndpsmb.c#L2243

I'm guess an issue in poppler?

Cheers,

Paul

Yup, indeed, it must be. I took ivan's suggestion and that indeed got me to a working Lucide viewer setup.

[Dariusz Piatkowski]

Hi ivan,

...Have you tried backleveling lucide to 1.3.5GA (2012-09-13) to see if that changes anything?

Thank you for that suggestion along with the confirmation this works for you. I figured that was going to be my next step if all else failed. Indeed, that release of Lucide works just fine here as well, so it may be the poppler library as Paul suggested (poppler.pentium4, 0.59.0-3.oc00 installed here), or perhaps something else?

I will log a new ticket for Gregg, hopefully he hasn't grown tired of seeing yet another defect being reported by 'yours trully' 8-P

...OT and out of curiosity what TCP/IP monitor are you using? The one I have always used stopped working when I upgraded to ArcaOS.

Well, I have been using 'PU Monitor' v2.1 (build 166) for a number of years now. It is very compact and highly customizable (field sizing, frequency of reporting, averaging over periods, etc), so it allows me to basically tailor the sampling frequency to produce a human readable and continuously updatable reporting feed. In other words, the numbers do not flash by so fast that it's impossible to tell what's going on.

I've attached a quick screen capture of where I have it overlayed on top of WarpCenter. It does have a built-in function to "dock" with WarpCenter, although I have not used that option in the past.

EDIT
====
Logged a new Lucide ticket, please see http://trac.netlabs.org/lucide/ticket/377#ticket

[Gregg Young]

I will log a new ticket for Gregg, hopefully he hasn't grown tired of seeing yet another defect being reported by 'yours trully' 8-P

Not a problem. Unfortunately I also suspect it is Poppler and that would mean that there may be little I can do about it. I will look at it when I get home.

[Paul Smedley]

Hey Gregg,

I will log a new ticket for Gregg, hopefully he hasn't grown tired of seeing yet another defect being reported by 'yours trully' 8-P

Not a problem. Unfortunately I also suspect it is Poppler and that would mean that there may be little I can do about it. I will look at it when I get home.

What build of poppler are you using, and how is it being called from Lucide? Happy to take a look at the poppler source and see if there's anything obvious in there...

Cheers,

Paul

[Gregg Young]

Hey Gregg,

I will log a new ticket for Gregg, hopefully he hasn't grown tired of seeing yet another defect being reported by 'yours trully' 8-P

Not a problem. Unfortunately I also suspect it is Poppler and that would mean that there may be little I can do about it. I will look at it when I get home.

What build of poppler are you using, and how is it being called from Lucide? Happy to take a look at the poppler source and see if there's anything obvious in there...

Cheers,

Paul

Hi Paul

We need someone to confirm at what point this was broken. Version 1.3.6 changed several things Poppler was updated from 0.20.3 to 0.42.0 and it changed from static linking to dynamic linking. I do not know if this version shows the problem or not. It also upgraded libc to 0.6.6 from 0.6.5 and changed to gcc 4.92 from 3.35.

Version 1.4.0 updated Poppler to 0.52.0 and the beta Dariusz is using is linked to 0.59.0. These are the netlabs RPM builds. Please note that this build  (0.59.0) has been patch to prevent the exhaustion of OS2 mutex handles.

Hopefully, 1.3.6 is still in netlabs incoming as I can't rebuild it since I no longer have the Poppler 0.42.0 libs and can't seem to find 1.3.6 locally (can probably get the libs/includes from bitwise if needed).  Thanks

Gregg