Geoportail-Luxembourg / geoportailv3

geoportailv3 is the implementation of the v3 of the map viewer of the luxembourgish geoportal
MIT License
25 stars 16 forks source link

printing is quite slow #596

Closed jaykayone closed 9 years ago

jaykayone commented 9 years ago

could this be improved somehow?

sbrunner commented 9 years ago

We needs more details to investigate it ...

jaykayone commented 9 years ago

a normal print like this one:

http://devv3.geoportail.lu/main/theme/main?version=3&zoom=16&X=683222&Y=6380978&lang=fr&crosshair=false&layers=376-560-555&opacities=1-0.9-0.9&bgLayer=topogr_global

1:10000, A4 portrait

takes 10 seconds: `` [Tue Jun 30 16:50:46.784188 2015] [:error] [pid 30010] 2015-06-30 16:50:46,783 INFO [c2cgeoportal.views.proxy][MainThread] Send query to URL: [Tue Jun 30 16:50:46.784265 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/report.pdf?. [Tue Jun 30 16:50:46.801775 2015] [:error] [pid 30010] 2015-06-30 16:50:46,801 INFO [c2cgeoportal.views.proxy][Dummy-2] Send query to URL: [Tue Jun 30 16:50:46.801804 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/status/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a.json?. [Tue Jun 30 16:50:47.812989 2015] [:error] [pid 30010] 2015-06-30 16:50:47,812 INFO [c2cgeoportal.views.proxy][MainThread] Send query to URL: [Tue Jun 30 16:50:47.813025 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/status/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a.json?. [Tue Jun 30 16:50:48.825019 2015] [:error] [pid 30010] 2015-06-30 16:50:48,824 INFO [c2cgeoportal.views.proxy][Dummy-2] Send query to URL: [Tue Jun 30 16:50:48.825059 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/status/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a.json?. [Tue Jun 30 16:50:49.844654 2015] [:error] [pid 30010] 2015-06-30 16:50:49,844 INFO [c2cgeoportal.views.proxy][Dummy-2] Send query to URL: [Tue Jun 30 16:50:49.844693 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/status/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a.json?. [Tue Jun 30 16:50:50.922991 2015] [:error] [pid 30010] 2015-06-30 16:50:50,922 INFO [c2cgeoportal.views.proxy][Dummy-2] Send query to URL: [Tue Jun 30 16:50:50.923024 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/status/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a.json?. [Tue Jun 30 16:50:51.935782 2015] [:error] [pid 30010] 2015-06-30 16:50:51,935 INFO [c2cgeoportal.views.proxy][MainThread] Send query to URL: [Tue Jun 30 16:50:51.935845 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/status/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a.json?. [Tue Jun 30 16:50:52.957349 2015] [:error] [pid 30010] 2015-06-30 16:50:52,957 INFO [c2cgeoportal.views.proxy][MainThread] Send query to URL: [Tue Jun 30 16:50:52.957607 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/status/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a.json?. [Tue Jun 30 16:50:53.991262 2015] [:error] [pid 30010] 2015-06-30 16:50:53,991 INFO [c2cgeoportal.views.proxy][Dummy-1] Send query to URL: [Tue Jun 30 16:50:53.991304 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/status/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a.json?. [Tue Jun 30 16:50:55.005867 2015] [:error] [pid 30010] 2015-06-30 16:50:55,005 INFO [c2cgeoportal.views.proxy][Dummy-2] Send query to URL: [Tue Jun 30 16:50:55.005913 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/status/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a.json?. [Tue Jun 30 16:50:56.022392 2015] [:error] [pid 30010] 2015-06-30 16:50:56,022 INFO [c2cgeoportal.views.proxy][Dummy-1] Send query to URL: [Tue Jun 30 16:50:56.022449 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/status/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a.json?. [Tue Jun 30 16:50:57.035151 2015] [:error] [pid 30010] 2015-06-30 16:50:57,034 INFO [c2cgeoportal.views.proxy][Dummy-2] Send query to URL: [Tue Jun 30 16:50:57.035197 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/status/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a.json?. [Tue Jun 30 16:50:57.054913 2015] [:error] [pid 30010] 2015-06-30 16:50:57,054 INFO [c2cgeoportal.views.proxy][Dummy-1] Send query to URL: [Tue Jun 30 16:50:57.054949 2015] [:error] [pid 30010] http://localhost:8083/print-main/print/geoportailv3/report/7470cbb1-2a5b-42f1-8635-57f48a45d7d9@e20f1286-f820-441a-b904-15c12576195a?.

in v2 it takes 4 seconds
jaykayone commented 9 years ago

screen shot 2015-06-30 at 16 55 31

jaykayone commented 9 years ago

here is the catalina.out:

17:00:00.441 [http-bio-0.0.0.0-8083-exec-3] INFO  p.mapfish.print.servlet.spec - spec:
    {"layout":"A4 portrait","attributes":{"scale":10000,"legend":[],"name":"","map":{"center":[683222,6380978],"scale":15436.042552792485,"rotation":0,"layers":[{"customParams":{"TRANSPARENT":true},"imageFormat":"png","layers":["category"],"opacity":1,"baseURL":"http://ws.geoportail.lu/mymaps?category_id=105","type":"wms"},{"customParams":{"TRANSPARENT":true},"imageFormat":"png","layers":["560"],"opacity":0.9,"baseURL":"http://devv3.geoportail.lu/main/wsgi/ogcproxywms","type":"wms"},{"customParams":{"TRANSPARENT":true},"imageFormat":"png","layers":["555"],"opacity":0.9,"baseURL":"http://devv3.geoportail.lu/main/wsgi/ogcproxywms","type":"wms"},{"style":"default","matrices":[{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[1,1],"tileSize":[256,256],"identifier":"00","scaleDenominator":5.590822640285715E8},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[2,2],"tileSize":[256,256],"identifier":"01","scaleDenominator":2.7954113201428574E8},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[4,4],"tileSize":[256,256],"identifier":"02","scaleDenominator":1.3977056600714287E8},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[8,8],"tileSize":[256,256],"identifier":"03","scaleDenominator":6.988528300357144E7},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[16,16],"tileSize":[256,256],"identifier":"04","scaleDenominator":3.494264150178572E7},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[32,32],"tileSize":[256,256],"identifier":"05","scaleDenominator":1.747132075089286E7},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[64,64],"tileSize":[256,256],"identifier":"06","scaleDenominator":8735660.375464285},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[128,128],"tileSize":[256,256],"identifier":"07","scaleDenominator":4367830.187714286},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[256,256],"tileSize":[256,256],"identifier":"08","scaleDenominator":2183915.093860714},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[512,512],"tileSize":[256,256],"identifier":"09","scaleDenominator":1091957.546932143},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[1024,1024],"tileSize":[256,256],"identifier":"10","scaleDenominator":545978.7734642858},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[2048,2048],"tileSize":[256,256],"identifier":"11","scaleDenominator":272989.38673285715},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[4096,4096],"tileSize":[256,256],"identifier":"12","scaleDenominator":136494.69336642858},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[8192,8192],"tileSize":[256,256],"identifier":"13","scaleDenominator":68247.34668321429},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[16384,16384],"tileSize":[256,256],"identifier":"14","scaleDenominator":34123.673341607144},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[32768,32768],"tileSize":[256,256],"identifier":"15","scaleDenominator":17061.836670785713},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[65536,65536],"tileSize":[256,256],"identifier":"16","scaleDenominator":8530.918335392857},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[131072,131072],"tileSize":[256,256],"identifier":"17","scaleDenominator":4265.459167714285},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[262144,262144],"tileSize":[256,256],"identifier":"18","scaleDenominator":2132.7295838500004},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[524288,524288],"tileSize":[256,256],"identifier":"19","scaleDenominator":1066.3647919250002}],"imageFormat":"image/png","matrixSet":"GLOBAL_WEBMERCATOR","layer":"topogr_global","dimensionParams":{},"baseURL":"http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/{TileMatrixSet}/{TileMatrix}/{TileCol}/{TileRow}.png","dimensions":[],"type":"WMTS","version":"1.0.0","requestEncoding":"REST"}],"projection":"EPSG:3857","dpi":300},"lang":"fr","url":"http://g-o.lu/v3/QnN1","qrimage":"http://devv3.geoportail.lu/main/wsgi/qr?url=http://g-o.lu/v3/QnN1"}}
17:00:00.444 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - No postConstruct method on parameter object.
17:00:00.446 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.448 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.449 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.451 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.452 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.454 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.454 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.454 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.455 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.455 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.455 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.456 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.456 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.457 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.457 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.457 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.458 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.458 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.458 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.459 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.459 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.459 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.460 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.460 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.460 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.461 [PrintJobManager-1] DEBUG o.mapfish.print.parser.MapfishParser - Executing postConstruct method on parameter object.
17:00:00.462 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.ProcessorDependencyGraph - Starting to execute processor graph: 
+ JasperReportBuilder(/usr/share/tomcat/webapps/print-main/print-apps/geoportailv3/.)
+ CreateMapProcessor
+ CreateScalebarProcessor
17:00:00.463 [ForkJoinPool-1-worker-50] INFO  o.m.p.processor.ProcessorGraphNode - Executing process: JasperReportBuilder(/usr/share/tomcat/webapps/print-main/print-apps/geoportailv3/.)
17:00:00.463 [ForkJoinPool-1-worker-52] INFO  o.m.p.processor.ProcessorGraphNode - Executing process: CreateScalebarProcessor
17:00:00.463 [ForkJoinPool-1-worker-51] INFO  o.m.p.processor.ProcessorGraphNode - Executing process: CreateMapProcessor
17:00:00.463 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.jasper.JasperReportBuilder - Destination file is already up to date: /var/cache/tomcat/temp/mapfish-print/geoportailv3/jasper-bin/./a0_landscape.jasper
17:00:00.463 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.jasper.JasperReportBuilder - Destination file is already up to date: /var/cache/tomcat/temp/mapfish-print/geoportailv3/jasper-bin/./a0_portrait.jasper
17:00:00.464 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.jasper.JasperReportBuilder - Destination file is already up to date: /var/cache/tomcat/temp/mapfish-print/geoportailv3/jasper-bin/./a1_landscape.jasper
17:00:00.464 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.jasper.JasperReportBuilder - Destination file is already up to date: /var/cache/tomcat/temp/mapfish-print/geoportailv3/jasper-bin/./a1_portrait.jasper
17:00:00.464 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.jasper.JasperReportBuilder - Destination file is already up to date: /var/cache/tomcat/temp/mapfish-print/geoportailv3/jasper-bin/./a2_landscape.jasper
17:00:00.464 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.jasper.JasperReportBuilder - Destination file is already up to date: /var/cache/tomcat/temp/mapfish-print/geoportailv3/jasper-bin/./a2_portrait.jasper
17:00:00.464 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.jasper.JasperReportBuilder - Destination file is already up to date: /var/cache/tomcat/temp/mapfish-print/geoportailv3/jasper-bin/./a3_landscape.jasper
17:00:00.465 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.jasper.JasperReportBuilder - Destination file is already up to date: /var/cache/tomcat/temp/mapfish-print/geoportailv3/jasper-bin/./a3_portrait.jasper
17:00:00.465 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.jasper.JasperReportBuilder - Destination file is already up to date: /var/cache/tomcat/temp/mapfish-print/geoportailv3/jasper-bin/./a4_landscape.jasper
17:00:00.465 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.jasper.JasperReportBuilder - Destination file is already up to date: /var/cache/tomcat/temp/mapfish-print/geoportailv3/jasper-bin/./a4_portrait.jasper
17:00:00.465 [ForkJoinPool-1-worker-50] INFO  o.m.p.processor.ProcessorGraphNode - Succeeded in executing process: JasperReportBuilder(/usr/share/tomcat/webapps/print-main/print-apps/geoportailv3/.)
17:00:00.466 [ForkJoinPool-1-worker-50] DEBUG o.m.p.processor.ProcessorGraphNode - Time taken to run processor: 'class org.mapfish.print.processor.jasper.JasperReportBuilder' was 2 ms
17:00:00.482 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.tiled.TileLoaderTask - 
    GET -- http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16941/11167.png
17:00:00.484 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16941/11167.png
17:00:00.496 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.tiled.TileLoaderTask - 
    GET -- http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16942/11167.png
17:00:00.497 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16942/11167.png
17:00:00.508 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.tiled.TileLoaderTask - 
    GET -- http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16943/11167.png
17:00:00.508 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16943/11167.png
17:00:00.511 [ForkJoinPool-1-worker-52] INFO  o.m.p.processor.ProcessorGraphNode - Succeeded in executing process: CreateScalebarProcessor
17:00:00.511 [ForkJoinPool-1-worker-52] DEBUG o.m.p.processor.ProcessorGraphNode - Time taken to run processor: 'class org.mapfish.print.processor.map.scalebar.CreateScalebarProcessor' was 48 ms
17:00:00.519 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.tiled.TileLoaderTask - 
    GET -- http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16941/11166.png
17:00:00.520 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16941/11166.png
17:00:00.532 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.tiled.TileLoaderTask - 
    GET -- http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16942/11166.png
17:00:00.533 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16942/11166.png
17:00:00.544 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.tiled.TileLoaderTask - 
    GET -- http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16943/11166.png
17:00:00.544 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16943/11166.png
17:00:00.556 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.tiled.TileLoaderTask - 
    GET -- http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16941/11165.png
17:00:00.556 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16941/11165.png
17:00:00.567 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.tiled.TileLoaderTask - 
    GET -- http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16942/11165.png
17:00:00.568 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16942/11165.png
17:00:00.579 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.tiled.TileLoaderTask - 
    GET -- http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16943/11165.png
17:00:00.580 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/GLOBAL_WEBMERCATOR/15/16943/11165.png
17:00:00.593 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.style.StyleParser - Content is not allowed in prolog.
17:00:00.593 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: raster
17:00:00.594 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: raster
17:00:03.034 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://devv3.geoportail.lu/main/wsgi/ogcproxywms?TRANSPARENT=true&BBOX=681942.3091944775%2C6379208.214843426%2C684501.6908055225%2C6382747.785156573&VERSION=1.1.1&FORMAT=image%2Fpng&SERVICE=WMS&HEIGHT=2708&REQUEST=GetMap&LAYERS=555&STYLES=&SRS=EPSG%3A3857&WIDTH=1958
17:00:03.544 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.style.StyleParser - Content is not allowed in prolog.
17:00:03.545 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: raster
17:00:03.545 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: raster
17:00:04.061 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://devv3.geoportail.lu/main/wsgi/ogcproxywms?TRANSPARENT=true&BBOX=681942.3091944775%2C6379208.214843426%2C684501.6908055225%2C6382747.785156573&VERSION=1.1.1&FORMAT=image%2Fpng&SERVICE=WMS&HEIGHT=2708&REQUEST=GetMap&LAYERS=560&STYLES=&SRS=EPSG%3A3857&WIDTH=1958
17:00:04.548 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.style.StyleParser - Content is not allowed in prolog.
17:00:04.549 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: raster
17:00:04.549 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: raster
17:00:05.015 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://ws.geoportail.lu/mymaps?TRANSPARENT=true&BBOX=681942.3091944775%2C6379208.214843426%2C684501.6908055225%2C6382747.785156573&VERSION=1.1.1&FORMAT=image%2Fpng&SERVICE=WMS&HEIGHT=2708&REQUEST=GetMap&CATEGORY_ID=105&LAYERS=category&STYLES=&SRS=EPSG%3A3857&WIDTH=1958
17:00:06.123 [ForkJoinPool-1-worker-51] DEBUG o.m.print.map.style.StyleParser - Content is not allowed in prolog.
17:00:06.124 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: raster
17:00:06.124 [ForkJoinPool-1-worker-51] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: raster
17:00:06.687 [ForkJoinPool-1-worker-51] INFO  o.m.p.processor.ProcessorGraphNode - Succeeded in executing process: CreateMapProcessor
17:00:06.688 [ForkJoinPool-1-worker-51] DEBUG o.m.p.processor.ProcessorGraphNode - Time taken to run processor: 'class org.mapfish.print.processor.map.CreateMapProcessor' was 6224 ms
17:00:06.688 [ForkJoinPool-1-worker-50] DEBUG o.m.p.p.ProcessorDependencyGraph - Finished executing processor graph: 
+ JasperReportBuilder(/usr/share/tomcat/webapps/print-main/print-apps/geoportailv3/.)
+ CreateMapProcessor
+ CreateScalebarProcessor
17:00:06.688 [PrintJobManager-1] INFO  o.mapfish.print.output.ValuesLogger - 
This log message details the parameters available for use in the Jasper templates for
  Mapfish Template: A4 portrait
  Jasper Template name: a4_portrait.jrxml
  The following parameters are available for use in the templates: 
    * layerGraphics (java.util.ArrayList)
    * pdfConfig (org.mapfish.print.config.PDFConfig)
    * scalebarSubReport (java.lang.String)
    * mapSubReport (java.lang.String)
    * graphic (java.net.URI)
    * clientHttpRequestFactory (org.mapfish.print.http.ConfigFileResolvingHttpRequestFactory)
    * template (org.mapfish.print.config.Template)
    * tempTaskDirectory (java.io.File)
    * legend (org.mapfish.print.attribute.DataSourceAttribute$DataSourceAttributeValue)
    * url (java.lang.String)
    * name (java.lang.String)
    * requestHeaders (org.mapfish.print.attribute.HttpRequestHeadersAttribute$Value)
    * mapContext (org.mapfish.print.attribute.map.MapfishMapContext)
    * scalebar (org.mapfish.print.attribute.ScalebarAttribute$ScalebarAttributeValues)
    * map (org.mapfish.print.attribute.map.MapAttribute$MapAttributeValues)
    * SUBREPORT_DIR (java.lang.String)
    * lang (java.lang.String)
    * scale (java.lang.String)
    * qrimage (java.lang.String)

17:00:06.707 [PrintJobManager-1] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Resolved request: LOGO_ACT.png using mapfish print config file loaders.
17:00:06.707 [PrintJobManager-1] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Executing http request: http://devv3.geoportail.lu/main/wsgi/qr?url=http://g-o.lu/v3/QnN1
17:00:06.756 [report subreports #1] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Resolved request: /var/cache/tomcat/temp/mapfish-print/task-2276994924737167445tmp/192d2af9-7802-414d-9c44-e79927efed3d_layer_0.png using mapfish print config file loaders.
17:00:06.792 [report subreports #1] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Resolved request: /var/cache/tomcat/temp/mapfish-print/task-2276994924737167445tmp/192d2af9-7802-414d-9c44-e79927efed3d_layer_1.png using mapfish print config file loaders.
17:00:06.793 [report subreports #1] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Resolved request: /var/cache/tomcat/temp/mapfish-print/task-2276994924737167445tmp/192d2af9-7802-414d-9c44-e79927efed3d_layer_2.png using mapfish print config file loaders.
17:00:06.793 [report subreports #1] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Resolved request: /var/cache/tomcat/temp/mapfish-print/task-2276994924737167445tmp/192d2af9-7802-414d-9c44-e79927efed3d_layer_3.png using mapfish print config file loaders.
17:00:06.804 [report subreports #1] DEBUG o.m.p.h.ConfigFileResolvingHttpRequestFactory - Resolved request: /var/cache/tomcat/temp/mapfish-print/task-2276994924737167445tmp/scalebar-graphic-8008557895370991589.tiff using mapfish print config file loaders.
17:00:09.996 [PrintJobManager-1] DEBUG o.mapfish.print.servlet.job.PrintJob - Successfully completed print job4d72d614-31d5-4835-893a-d58382cf1c2f@e20f1286-f820-441a-b904-15c12576195a
spec:
    {"app":"geoportailv3","outputFormat":"pdf","layout":"A4 portrait","attributes":{"scale":10000,"requestHeaders":{"requestHeaders":{"content-type":["application/json; charset=UTF-8"],"connection":["Keep-Alive"],"accept-language":["fr-LU,en-US;q=0.7,en;q=0.3"],"host":["devv3.geoportail.lu"],"x-forwarded-for":["148.110.80.240"],"accept":["application/json, text/plain, */*"],"x-forwarded-host":["devv3.geoportail.lu"],"user-agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:38.0) Gecko/20100101 Firefox/38.0"],"pragma":["no-cache"],"cache-control":["no-cache"],"content-length":["4123"],"accept-encoding":["gzip, deflate"],"referer":["http://devv3.geoportail.lu/main/theme/main?version=3&zoom=15&X=683222&Y=6380978&lang=fr&crosshair=false&layers=376-560-555&opacities=1-0.9-0.9&bgLayer=topogr_global"],"x-forwarded-server":["devv3.geoportal.lu"]}},"legend":[],"name":"","map":{"center":[683222,6380978],"scale":15436.042552792485,"rotation":0,"layers":[{"customParams":{"TRANSPARENT":true},"imageFormat":"png","layers":["category"],"opacity":1,"baseURL":"http://ws.geoportail.lu/mymaps?category_id=105","type":"wms"},{"customParams":{"TRANSPARENT":true},"imageFormat":"png","layers":["560"],"opacity":0.9,"baseURL":"http://devv3.geoportail.lu/main/wsgi/ogcproxywms","type":"wms"},{"customParams":{"TRANSPARENT":true},"imageFormat":"png","layers":["555"],"opacity":0.9,"baseURL":"http://devv3.geoportail.lu/main/wsgi/ogcproxywms","type":"wms"},{"style":"default","matrices":[{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[1,1],"tileSize":[256,256],"identifier":"00","scaleDenominator":5.590822640285715E8},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[2,2],"tileSize":[256,256],"identifier":"01","scaleDenominator":2.7954113201428574E8},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[4,4],"tileSize":[256,256],"identifier":"02","scaleDenominator":1.3977056600714287E8},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[8,8],"tileSize":[256,256],"identifier":"03","scaleDenominator":6.988528300357144E7},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[16,16],"tileSize":[256,256],"identifier":"04","scaleDenominator":3.494264150178572E7},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[32,32],"tileSize":[256,256],"identifier":"05","scaleDenominator":1.747132075089286E7},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[64,64],"tileSize":[256,256],"identifier":"06","scaleDenominator":8735660.375464285},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[128,128],"tileSize":[256,256],"identifier":"07","scaleDenominator":4367830.187714286},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[256,256],"tileSize":[256,256],"identifier":"08","scaleDenominator":2183915.093860714},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[512,512],"tileSize":[256,256],"identifier":"09","scaleDenominator":1091957.546932143},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[1024,1024],"tileSize":[256,256],"identifier":"10","scaleDenominator":545978.7734642858},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[2048,2048],"tileSize":[256,256],"identifier":"11","scaleDenominator":272989.38673285715},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[4096,4096],"tileSize":[256,256],"identifier":"12","scaleDenominator":136494.69336642858},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[8192,8192],"tileSize":[256,256],"identifier":"13","scaleDenominator":68247.34668321429},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[16384,16384],"tileSize":[256,256],"identifier":"14","scaleDenominator":34123.673341607144},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[32768,32768],"tileSize":[256,256],"identifier":"15","scaleDenominator":17061.836670785713},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[65536,65536],"tileSize":[256,256],"identifier":"16","scaleDenominator":8530.918335392857},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[131072,131072],"tileSize":[256,256],"identifier":"17","scaleDenominator":4265.459167714285},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[262144,262144],"tileSize":[256,256],"identifier":"18","scaleDenominator":2132.7295838500004},{"topLeftCorner":[-2.00375083428E7,2.00375083428E7],"matrixSize":[524288,524288],"tileSize":[256,256],"identifier":"19","scaleDenominator":1066.3647919250002}],"imageFormat":"image/png","matrixSet":"GLOBAL_WEBMERCATOR","layer":"topogr_global","dimensionParams":{},"baseURL":"http://wmts.geoportail.lu/mapproxy_4_v3/wmts/topogr_global/{TileMatrixSet}/{TileMatrix}/{TileCol}/{TileRow}.png","dimensions":[],"type":"WMTS","version":"1.0.0","requestEncoding":"REST"}],"projection":"EPSG:3857","dpi":300},"lang":"fr","url":"http://g-o.lu/v3/QnN1","qrimage":"http://devv3.geoportail.lu/main/wsgi/qr?url=http://g-o.lu/v3/QnN1"}}
17:00:09.997 [PrintJobManager-1] DEBUG o.mapfish.print.servlet.job.PrintJob - Print Job 4d72d614-31d5-4835-893a-d58382cf1c2f@e20f1286-f820-441a-b904-15c12576195a completed in 9553ms