V5 self hosted, slow to save, runs PDF gen multiple times?

I’m trying to troubleshoot why a self hosted install on a dedicated 8 core ubuntu VM with 3 gigs of ram is slow to save (using snappdf generator).

The odd part I found while troubleshooting is that the logo is accessed once for live review, but three times for the save function. Does this mean that something is going wrong during save and the system has to retry several times?
This test is run on a test quote with just one line item “test” which results in a single page PDF.

10.10.0.188 - - [06/Feb/2022:16:15:29 +0000] "GET /storage/kxZLV9Bjpb3XyRpQsjwdGv3uVA0RtX3H2NS887OSJlPlIYxIdhCDWodZsDzTu3xH/zGQ0J13I2VrMZG8k1SRP5y6oVNptDu7cfugIjhgb.png HTTP/1.0" 200 5119 "-" "-"
10.10.0.188 - - [06/Feb/2022:16:15:29 +0000] "POST /api/v1/live_preview?entity=quote&entity_id=l4zbqx2apr HTTP/1.0" 200 57561 "https://url.xyz/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.80 Safari/537.36 Edg/98.0.1108.43"
10.10.0.188 - - [06/Feb/2022:16:15:30 +0000] "GET /js/pdf.worker.min.js HTTP/1.0" 200 637923 "https://url.xyz/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.80 Safari/537.36 Edg/98.0.1108.43"

10.10.0.188 - - [06/Feb/2022:16:15:36 +0000] "GET /storage/kxZLV9Bjpb3XyRpQsjwdGv3uVA0RtX3H2NS887OSJlPlIYxIdhCDWodZsDzTu3xH/zGQ0J13I2VrMZG8k1SRP5y6oVNptDu7cfugIjhgb.png HTTP/1.0" 200 5119 "-" "-"
10.10.0.188 - - [06/Feb/2022:16:15:38 +0000] "GET /storage/kxZLV9Bjpb3XyRpQsjwdGv3uVA0RtX3H2NS887OSJlPlIYxIdhCDWodZsDzTu3xH/zGQ0J13I2VrMZG8k1SRP5y6oVNptDu7cfugIjhgb.png HTTP/1.0" 200 5119 "-" "-"
10.10.0.188 - - [06/Feb/2022:16:15:43 +0000] "GET /storage/kxZLV9Bjpb3XyRpQsjwdGv3uVA0RtX3H2NS887OSJlPlIYxIdhCDWodZsDzTu3xH/zGQ0J13I2VrMZG8k1SRP5y6oVNptDu7cfugIjhgb.png HTTP/1.0" 200 5119 "-" "-"
10.10.0.188 - - [06/Feb/2022:16:15:44 +0000] "PUT /api/v1/quotes/l4zbqx2apr?include=history,activities HTTP/1.0" 200 16705 "https://url.xyz/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.80 Safari/537.36 Edg/98.0.1108.43"

Is there any way to turn on debugging for more internal information about the save process?

Thank you,
Gene

Hi,

Have you enabled the queue? It should make saving much quicker.

@david may have additional info to provide.

1 Like

Are you talking about email queue? I could not find any other reference to queue in documentation.

Thank you

The docs are here:

https://invoiceninja.github.io/docs/self-host-installation/#cron-configuration-1

With that server spec, the system should be plenty fast.

To isolate the issue. I would suggest changing the PDF_GENERATOR variable in your .env from snappdf to hosted_ninja

If this improves the save times, then the issue will definitely be your system trying to generate the PDFs.

Thanks @david, hosted_ninja has definitely made a huge difference. 2 seconds save vs 16 it took before

Logs still show three requests for the logo during the save, but they occur within a second or so, much faster.

10.10.0.188 - - [07/Feb/2022:03:38:35 +0000] "GET /storage/kxZLV9Bjpb3XyRpQsjwdGv3uVA0RtX3H2NS887OSJlPlIYxIdhCDWodZsDzTu3xH/1V8pI1ybJPAFcWYM4qGsfMKp32jHpf8xOaPYUpLS.png HTTP/1.0" 200 5119 "-" "-"
10.10.0.188 - - [07/Feb/2022:03:38:36 +0000] "GET /storage/kxZLV9Bjpb3XyRpQsjwdGv3uVA0RtX3H2NS887OSJlPlIYxIdhCDWodZsDzTu3xH/1V8pI1ybJPAFcWYM4qGsfMKp32jHpf8xOaPYUpLS.png HTTP/1.0" 200 5119 "-" "-"
10.10.0.188 - - [07/Feb/2022:03:38:36 +0000] "GET /storage/kxZLV9Bjpb3XyRpQsjwdGv3uVA0RtX3H2NS887OSJlPlIYxIdhCDWodZsDzTu3xH/1V8pI1ybJPAFcWYM4qGsfMKp32jHpf8xOaPYUpLS.png HTTP/1.0" 200 5119 "-" "-"
10.10.0.188 - - [07/Feb/2022:03:38:37 +0000] "PUT /api/v1/quotes/l4zbqx2apr?include=history,activities HTTP/1.0" 200 15912 "https://url.xyz/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.80 Safari/537.36 Edg/98.0.1108.43"

I was trying to get snappdf to work, thinking this should provide the fastest / best performance. But at I am happy with 8x performance improvement.

At this point I’ll try contacting the snappdf team / forum and see what advice they could provide. I’ll update the tread if I’ll find the root cause of issue with my setup & snappdf slowdown.

@hillel, Thank you for the link. I guess searching for documentation mainly points to rev 4. laravel Supervisor for the queue management sounds interesting, though it seems I can do the same thing with a simpler cron. I’ll have to look further into the advantage of supervisor vs cron for the queue management and update this thread with the results.

@gene

You may want to try settings in your .env LOCAL_DOWNLOAD=true

and see if that improves snappdf, i think it may be a DNS issue if it is taking that long, it really shouldn’t take more than a second or two to generate the PDF end to end.

1 Like

@david, thanks LOCAL_DOWNLOAD brought the requests for the logo from 3 down to 1. Otherwise, it didn’t seem to speed up the hosted or snappdf generation.

At this point I’m pretty sure the issue lies with snappdf config. I’ll try to troubleshoot it further tomorrow and upgrade the tread with my findings.

Thank you @david and @hillel again for the weekend support and advice. Above and beyond, both of you.

P.S. For those who run into a similar 3 request question, I found that I had to run php7.4 artisan optimize in appropriate directory in order for LOCAL_DOWNLOAD change to the.env file for effect to activate. Saving and rebooting the system along was seemingly not enough.

Update: I found a permissions issue with the folder snappdf would download the crome to. IT was owned by the user I use to connect, not the www-data user that invoice ninja operates under. Seems, when installing snappdf, it is a good idea to run the composer commands as sudo -u www-data user, otherwise check the permissions / ownership of the following folder:
/usr/share/nginx/invoiceninja/vendor/beganovich/snappdf/versions/

After the change snappdf seems to be as fast as hosted pdf generation.

Disabling LOCAL_DOWNLOAD parameter, resulted in the three requests for logo during save, even with snappdf operating at the optimal speed. This confirms that the number of requests does not indicate failure or retries by the pdf generator.

Thank you again, @david and @hillel for your assistance.

1 Like

Another update, I finally figured out what was going wrong with QUEUE system, in my case a second (hidden) sync config (from the sample .env I’ve customized) was overriding the database QUEUE I’ve tried to use:

$ cat /usr/share/nginx/invoiceninja/.env | grep QUEUE
QUEUE_CONNECTION=database
QUEUE_CONNECTION=sync

Removing the conflicting sync setting greatly increased the performance and now saving takes only 164 ms.

I’ve learned to save often, as sometimes connectivity to the server is lost and any active edits are lost with it. I wish there was an easy way to get back old live previews to copy and paste the lost edits.

Thanks for the update, glad to hear the performance is improved.

1 Like