speed optimalization
I've just recently installed a trial version of prince and I'm now benchmarking it to evaluate the speed. It seems to me that the conversion speed itself is very quick, even for large documents it's only 1-2 seconds. But what I cannot understand is why there is a 4-6 seconds delay between the log entry "begin" and the log entry "Loading document"?
Even for a small, 1 page documents, there is this delay, and it's the same for large documents 100+ pages. This is the the log file for a small, 1 page document:
Tue Apr 17 13:08:24 2012: ---- begin
Tue Apr 17 13:08:30 2012: Loading document...
Tue Apr 17 13:08:30 2012: Converting document...
Tue Apr 17 13:08:30 2012: finished: success
Tue Apr 17 13:08:30 2012: ---- end
I'm using prince through the PHP-class, and I only call prince at the end of my script, just before the headers.
Strange. Do you get this same behaviour if you run Prince manually from the command-line?
No, when I run it from the command-line the speed is impeccable. It converts several hundred-pages documents in few seconds, and there is no delay between "begin" and "loading".
Could it be an issue with the PHP-class?
No, when I run it from the command line, the speed is impeccable and there is no delay between "begin" and "loading".
Could there be an issue with the PHP-class?
How are you calling Prince? Are you passing in a filename to convert, or a string of literal HTML, or using the passthru mechanism?
mikeday wrote:
How are you calling Prince? Are you passing in a filename to convert, or a string of literal HTML, or using the passthru mechanism?
I'm passing a string of literal HTML using:
$prince->convert_string_to_passthru($HTML_string);
I've benchmarked the php-script, and the only significant delay in the PHP-script is the execution of this command.
Do you still get a slowdown if the string is really short, eg. "<html><body>Hello!</body></html>".
mikeday wrote:
Do you still get a slowdown if the string is really short, eg. "<html><body>Hello!</body></html>".
yes, the delay seems to be pretty constant. This is the log file when passing the string you suggested:
Fri Apr 20 15:02:18 2012: ---- begin
Fri Apr 20 15:02:23 2012: Loading document...
Fri Apr 20 15:02:24 2012: Converting document...
Fri Apr 20 15:02:24 2012: finished: success
Fri Apr 20 15:02:24 2012: ---- end
Strange. Can you check inside prince.php in the method convert_internal_string_to_passthru(), is the delay happening during the call to proc_open()?
mikeday wrote:
Strange. Can you check inside prince.php in the method convert_internal_string_to_passthru(), is the delay happening during the call to proc_open()?
No, it doesn't seem that that's the bottleneck. There's absolutely no delay there (small document):
[Sat Apr 21 17:30:44 2012] [error] [client 84.215.58.209] Before proc_open convert_internal_string_to_passthru: 1335022244.8, referer: http://basistjeneste.no/cv.php
[Sat Apr 21 17:30:44 2012] [error] [client 84.215.58.209] After proc_open convert_internal_string_to_passthru: 1335022244.8, referer: http://basistjeneste.no/cv.php
The large number (1335022244.8) is output from the php function microtime(true), and as you can see it's identical before and after the call to proc_open.
After some more benchmarking, it seems the delay is with the fpassthru($pipes[1]) in the if (is_resource($process)) of the convert_internal_string_to_passthru() function. This has a long execution time of 4-7 seconds regardless of string size...
This becomes more and more interesting! Can you try passing the --debug flag to Prince, to get more output in the log file? You can add it in getCommandLine(), after --server.
mikeday wrote:
This becomes more and more interesting! Can you try passing the --debug flag to Prince, to get more output in the log file? You can add it in getCommandLine(), after --server.
Here's the output:
Sun Apr 22 10:08:44 2012: ---- begin
Sun Apr 22 10:08:44 2012: debug: loading license: /usr/local/lib/prince/license/license.dat
Sun Apr 22 10:08:48 2012: loading style sheet: /usr/local/lib/prince/style/fonts.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: /usr/local/lib/prince/style/fonts.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: type: no
Sun Apr 22 10:08:48 2012: Loading document...
Sun Apr 22 10:08:48 2012: loading XML input: -
Sun Apr 22 10:08:48 2012: debug: loaded document: -
Sun Apr 22 10:08:48 2012: debug: sniffed doctype: XHTML (no namespace)
Sun Apr 22 10:08:48 2012: loading style sheet: /usr/local/lib/prince/style/xhtml.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: /usr/local/lib/prince/style/xhtml.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: type: no
Sun Apr 22 10:08:48 2012: loading style sheet: /usr/local/lib/prince/style/common.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: /usr/local/lib/prince/style/common.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: type: no
Sun Apr 22 10:08:48 2012: loading style sheet: /usr/local/lib/prince/style/hyph.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: /usr/local/lib/prince/style/hyph.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: type: no
Sun Apr 22 10:08:48 2012: loading style sheet: /usr/local/lib/prince/style/mathml.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: /usr/local/lib/prince/style/mathml.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: type: no
Sun Apr 22 10:08:48 2012: loading style sheet: /usr/local/lib/prince/style/svg.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: /usr/local/lib/prince/style/svg.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: type: no
Sun Apr 22 10:08:48 2012: loading style sheet: cv.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: cv.css
Sun Apr 22 10:08:48 2012: debug: loaded resource: type: no
Sun Apr 22 10:08:48 2012: debug: prepack
Sun Apr 22 10:08:48 2012: loading image: ../bilder/1.jpeg
Sun Apr 22 10:08:48 2012: debug: loaded resource: ../bilder/1.jpeg
Sun Apr 22 10:08:48 2012: debug: loaded resource: type: no
Sun Apr 22 10:08:48 2012: Converting document...
Sun Apr 22 10:08:48 2012: debug: pack
Sun Apr 22 10:08:48 2012: debug: font request: bold Times New Roman, Georgia, serif
Sun Apr 22 10:08:48 2012: debug: font scan: Times New Roman
Sun Apr 22 10:08:48 2012: debug: font scan: Times New Roman, 0 matches
Sun Apr 22 10:08:48 2012: debug: font scan: Georgia
Sun Apr 22 10:08:48 2012: debug: font scan: Georgia, 0 matches
Sun Apr 22 10:08:48 2012: debug: font scan: DejaVu Serif
Sun Apr 22 10:08:48 2012: debug: font scan: DejaVu Serif, 8 matches
Sun Apr 22 10:08:48 2012: debug: font scan: OpenSymbol
Sun Apr 22 10:08:48 2012: debug: font scan: OpenSymbol, 1 matches
Sun Apr 22 10:08:48 2012: debug: font scan: AR PL UMing CN
Sun Apr 22 10:08:48 2012: debug: font scan: AR PL UMing CN, 0 matches
Sun Apr 22 10:08:48 2012: debug: font scan: AR PL SungtiL GB
Sun Apr 22 10:08:48 2012: debug: font scan: AR PL SungtiL GB, 0 matches
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Hindi
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Hindi, 1 matches
Sun Apr 22 10:08:48 2012: debug: font scan: Ani
Sun Apr 22 10:08:48 2012: debug: font scan: Ani, 0 matches
Sun Apr 22 10:08:48 2012: debug: font scan: Mukti Narrow
Sun Apr 22 10:08:48 2012: debug: font scan: Mukti Narrow, 2 matches
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Punjabi
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Punjabi, 1 matches
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Gujarati
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Gujarati, 1 matches
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Tamil
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Tamil, 1 matches
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Telugu
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Telugu, 0 matches
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Kannada
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Kannada, 0 matches
Sun Apr 22 10:08:48 2012: debug: font scan: MalOtf
Sun Apr 22 10:08:48 2012: debug: font scan: MalOtf, 0 matches
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Oriya
Sun Apr 22 10:08:48 2012: debug: font scan: Lohit Oriya, 0 matches
Sun Apr 22 10:08:48 2012: used font: DejaVu Serif, Bold
Sun Apr 22 10:08:48 2012: debug: font request: Times New Roman, Georgia, serif
Sun Apr 22 10:08:48 2012: used font: DejaVu Serif, Book
Sun Apr 22 10:08:48 2012: debug: font request: serif
Sun Apr 22 10:08:48 2012: debug: writing output: -
Sun Apr 22 10:08:48 2012: loading image: ../bilder/1.jpeg
Sun Apr 22 10:08:48 2012: debug: loaded resource: ../bilder/1.jpeg
Sun Apr 22 10:08:48 2012: debug: loaded resource: type: no
Sun Apr 22 10:08:48 2012: finished: success
Sun Apr 22 10:08:48 2012: ---- end
Okay, that makes no sense at all, as the license file is tiny and will never take four seconds to load. Which operating system are you running on? There are some strange issues that only affect PHP on MacOS X.
mikeday wrote:
Okay, that makes no sense at all, as the license file is tiny and will never take four seconds to load. Which operating system are you running on? There are some strange issues that only affect PHP on MacOS X.
yes, I also found this strange...
The server is running Ubuntu 10.04.4 server edition.
Could it be a problem with the PHP-configuration?
when you asked me about the OS, I realized that I could use the .deb files from your site. So I uninstalled the version I compiled from the generic linux package and installed the deb instead. Somehow this solved the problem!
It is now extremely quick, even for huge documents!
Thanks for the help, and sorry for the mess...
Glad to hear it is working! Guess it must have been an issue with dynamic libraries, or something.
