[OSM-dev] Rendering Chain Issue
Richard Ive
richard.ive at metafour.com
Tue Jun 19 22:02:20 BST 2012
Thanks for your response!
My output from the daemon log doesn't show anything about threads crashing.
Jun 19 21:05:24 maptile tirex-backend-manager[7840]: sending HUP to worker
'mapnik' with pid 7992 (due to timeout)
Jun 19 21:05:40 maptile tirex-backend-manager[7840]: sending TERM to worker
'mapnik' with pid 7992 (due to timeout)
Jun 19 21:05:40 maptile tirex-backend-manager[7840]: child 7992 terminated
(exit_code=0, signal=15)
Jun 19 21:05:40 maptile tirex-backend-manager[7840]: renderer mapnik
started with pid 15666
Jun 19 21:05:41 maptile tirex-backend-mapnik[15666]: Renderer started
(name=mapnik)
Jun 19 21:07:39 maptile tirex-backend-manager[7840]: sending HUP to worker
'mapnik' with pid 9375 (due to timeout)
Jun 19 21:07:39 maptile tirex-backend-manager[7840]: child 9375 terminated
(exit_code=127, signal=0)
Jun 19 21:07:39 maptile tirex-backend-manager[7840]: renderer mapnik
started with pid 15683
Jun 19 21:07:39 maptile tirex-backend-mapnik[15683]: Renderer started
(name=mapnik)
Jun 19 21:07:44 maptile tirex-backend-manager[7840]: sending HUP to worker
'mapnik' with pid 7991 (due to timeout)
Jun 19 21:07:44 maptile tirex-backend-manager[7840]: child 7991 terminated
(exit_code=127, signal=0)
Jun 19 21:07:44 maptile tirex-backend-manager[7840]: renderer mapnik
started with pid 15694
Jun 19 21:07:44 maptile tirex-backend-mapnik[15694]: Renderer started
(name=mapnik)
Jun 19 21:07:46 maptile tirex-backend-manager[7840]: sending HUP to worker
'mapnik' with pid 9523 (due to timeout)
Jun 19 21:07:46 maptile tirex-backend-manager[7840]: child 9523 terminated
(exit_code=127, signal=0)
Jun 19 21:07:46 maptile tirex-backend-manager[7840]: renderer mapnik
started with pid 15695
Jun 19 21:07:46 maptile tirex-backend-mapnik[15695]: Renderer started
(name=mapnik)
Jun 19 21:07:49 maptile tirex-backend-manager[7840]: sending HUP to worker
'mapnik' with pid 7995 (due to timeout)
Jun 19 21:07:49 maptile tirex-backend-manager[7840]: child 7995 terminated
(exit_code=127, signal=0)
Jun 19 21:07:49 maptile tirex-backend-manager[7840]: renderer mapnik
started with pid 15696
Jun 19 21:07:49 maptile tirex-backend-mapnik[15696]: Renderer started
(name=mapnik)
Jun 19 21:07:57 maptile tirex-master[7852]: Job with
id=1340135843_499660176 timed out on rendering list (map=metamaps z=7 x=64
y=40)
Jun 19 21:08:09 maptile tirex-backend-manager[7840]: sending HUP to worker
'mapnik' with pid 7994 (due to timeout)
Jun 19 21:08:09 maptile tirex-backend-manager[7840]: child 7994 terminated
(exit_code=127, signal=0)
Jun 19 21:08:09 maptile tirex-backend-manager[7840]: renderer mapnik
started with pid 15697
Jun 19 21:08:09 maptile tirex-backend-mapnik[15697]: Renderer started
(name=mapnik)
Tirex appears to match up with Mapnik.
root at maptile:/var/log# tirex-status -o
ps
Tirex Master Status (updated=2012-06-19 21:55:10)
Master server:
started=2012-06-19 16:07:57 pid=7852
Statistics:
count_error=0
count_expired=0
count_rendered[metamaps]=0, 0, 0, 0, 0, 0, 0, 2, 0, 0, 0, 0, 0, 1, 0, 4
count_requested=12
count_timeouted=4
sum_render_time[metamaps]=0, 0, 0, 0, 0, 0, 0, 536493, 0, 0, 0, 0, 0,
23375, 0, 60094
Queue:
Prio Size Maxsize Age
1 0 1
2 0 1
all 0 1
Buckets: (load=0)
Name Priority Rendering MaxRend Maxload Active Can
Queued Age
live 1- 9 1 19 28 yes yes
0
important 10- 19 0 15 20 yes yes
0
background 20- 0 4 15 yes yes
0
Currently rendering: (num=1)
Map X Y Z Prio Age
metamaps 64 40 7 1 132
root at maptile:/var/log# ps -ef | grep -i mapnik
tirex 7845 7840 0 16:07 ? 00:00:38 mapnik: idle
tirex 7993 7840 0 16:17 ? 00:00:07 mapnik: idle
tirex 7996 7840 0 16:17 ? 00:00:07 mapnik: rendering z=7 x=64
y=40 map=metamaps
tirex 15666 7840 0 21:05 ? 00:00:00 mapnik: idle
tirex 15683 7840 0 21:07 ? 00:00:00 mapnik: idle
tirex 15694 7840 0 21:07 ? 00:00:00 mapnik: idle
tirex 15695 7840 0 21:07 ? 00:00:00 mapnik: idle
tirex 15696 7840 0 21:07 ? 00:00:00 mapnik: idle
tirex 15697 7840 0 21:08 ? 00:00:00 mapnik: idle
root 16302 16250 0 21:55 pts/0 00:00:00 grep --color=auto -i mapnik
root at maptile:/var/log#
I'm really struggling now. I enabled verbose logging in Tirex, which
doesn't seem to have produces any better logging anywhere. Tirex isn't
crashing, it just refuses to accept connections while this one tile is in
the queue, or until HTTPD times out.
Here's my apache2 error.log
[Tue Jun 19 21:55:36 2012] [info] [client 10.0.102.1] Global planet file
time stamp (/var/lib/mod_tile//planet-import-complete) updated to Tue, 29
May 2012 12:22:56 GMT, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:55:36 2012] [debug] ./mod_tile.c(864): [client 10.0.102.1]
tile_handler_serve: xml(metamaps) z(8) x(129) y(87), referer:
http://maptiles.cust.m4.net/
[Tue Jun 19 21:55:36 2012] [debug] ./mod_tile.c(325): [client 10.0.102.1]
expires(tile_serve), uri(/tiles/metamaps/8/130/87.png),
filename(/var/lib/mod_tile/metamaps/8/0/0/0/133/0.meta),
path_info((null))\n, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:55:36 2012] [debug] ./mod_tile.c(363): [client 10.0.102.1]
caching heuristics: next planet render -1240360; zoom level based 11104000;
last modified 0\n, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:55:36 2012] [debug] ./mod_tile.c(374): [client 10.0.102.1]
Setting tiles maxAge to 11113074\n, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:55:36 2012] [debug] ./mod_tile.c(325): [client 10.0.102.1]
expires(tile_serve), uri(/tiles/metamaps/8/129/87.png),
filename(/var/lib/mod_tile/metamaps/8/0/0/0/133/0.meta),
path_info((null))\n, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:55:36 2012] [debug] ./mod_tile.c(363): [client 10.0.102.1]
caching heuristics: next planet render -1240360; zoom level based 11104000;
last modified 0\n, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:55:36 2012] [debug] ./mod_tile.c(374): [client 10.0.102.1]
Setting tiles maxAge to 11113074\n, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:55:36 2012] [debug] ./mod_tile.c(325): [client 10.0.102.1]
expires(tile_serve), uri(/tiles/metamaps/8/125/87.png),
filename(/var/lib/mod_tile/metamaps/8/0/0/0/117/128.meta),
path_info((null))\n, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:55:36 2012] [debug] ./mod_tile.c(363): [client 10.0.102.1]
caching heuristics: next planet render -1240360; zoom level based 11104000;
last modified 0\n, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:55:36 2012] [debug] ./mod_tile.c(374): [client 10.0.102.1]
Setting tiles maxAge to 11113074\n, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:55:42 2012] [debug] ./mod_tile.c(925): [client 127.0.0.1]
tile_translate: uri(*)
[Tue Jun 19 21:55:42 2012] [debug] ./mod_tile.c(950): [client 127.0.0.1]
tile_translate: testing baseuri(/tiles/metamaps/) name(metamaps)
extension(png)
[Tue Jun 19 21:55:42 2012] [debug] ./mod_tile.c(1016): [client 127.0.0.1]
tile_translate: No suitable tile layer found
[Tue Jun 19 21:55:43 2012] [debug] ./mod_tile.c(925): [client 127.0.0.1]
tile_translate: uri(*)
[Tue Jun 19 21:55:43 2012] [debug] ./mod_tile.c(950): [client 127.0.0.1]
tile_translate: testing baseuri(/tiles/metamaps/) name(metamaps)
extension(png)
[Tue Jun 19 21:55:43 2012] [debug] ./mod_tile.c(1016): [client 127.0.0.1]
tile_translate: No suitable tile layer found
[Tue Jun 19 21:56:23 2012] [debug] ./mod_tile.c(197): [client 10.0.102.1]
request_tile: Request xml(metamaps) z(7) x(67) y(41) could not be rendered
in 50 seconds, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] ./mod_tile.c(758): [client 10.0.102.1]
tile_storage_hook: Missing tile was not rendered in time. Returning File
Not Found, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] mod_deflate.c(615): [client 10.0.102.1]
Zlib: Compressed 224 to 176 : URL /tiles/metamaps/7/67/41.png, referer:
http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] ./mod_tile.c(197): [client 10.0.102.1]
request_tile: Request xml(metamaps) z(7) x(67) y(44) could not be rendered
in 50 seconds, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] ./mod_tile.c(758): [client 10.0.102.1]
tile_storage_hook: Missing tile was not rendered in time. Returning File
Not Found, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] mod_deflate.c(615): [client 10.0.102.1]
Zlib: Compressed 224 to 176 : URL /tiles/metamaps/7/67/44.png, referer:
http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] ./mod_tile.c(197): [client 10.0.102.1]
request_tile: Request xml(metamaps) z(7) x(67) y(42) could not be rendered
in 50 seconds, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] ./mod_tile.c(758): [client 10.0.102.1]
tile_storage_hook: Missing tile was not rendered in time. Returning File
Not Found, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] mod_deflate.c(615): [client 10.0.102.1]
Zlib: Compressed 224 to 176 : URL /tiles/metamaps/7/67/42.png, referer:
http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] ./mod_tile.c(197): [client 10.0.102.1]
request_tile: Request xml(metamaps) z(7) x(67) y(43) could not be rendered
in 50 seconds, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] ./mod_tile.c(758): [client 10.0.102.1]
tile_storage_hook: Missing tile was not rendered in time. Returning File
Not Found, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] mod_deflate.c(615): [client 10.0.102.1]
Zlib: Compressed 224 to 176 : URL /tiles/metamaps/7/67/43.png, referer:
http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] ./mod_tile.c(197): [client 10.0.102.1]
request_tile: Request xml(metamaps) z(7) x(67) y(40) could not be rendered
in 50 seconds, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] ./mod_tile.c(758): [client 10.0.102.1]
tile_storage_hook: Missing tile was not rendered in time. Returning File
Not Found, referer: http://maptiles.cust.m4.net/
[Tue Jun 19 21:56:23 2012] [debug] mod_deflate.c(615): [client 10.0.102.1]
Zlib: Compressed 224 to 176 : URL /tiles/metamaps/7/67/40.png, referer:
http://maptiles.cust.m4.net/
Any more ideas?
Thanks again.
On 19 June 2012 15:52, Frederik Ramm <frederik at remote.org> wrote:
> Hi,
>
>
> On 06/19/2012 03:45 PM, Richard Ive wrote:
>
>> In my second screen shot you can see the two tiles that get requested
>> just before the freeze. I can consistently make this happen and resolve
>> the hang by restarting Tirex, which would suggest the problem is there,
>> however looking through all the logs I don't see anything related to
>> this issue.
>>
>
> If a Tirex render process dies - something that you would see in the
> "daemon" syslog - then the effect is that tirex-master still lists the
> request as being rendered but there will be no "mapnik" process in the
> system that claims to be rendering this job. If this happens often enough,
> the Tirex queue will be full. Look at tirex-status and compare the list of
> tiles being rendered with the list of "mapnik" processes. If processes are
> indeed dying, activate verbose=true in the Tirex config and try to find
> out; it might well be a funny Mapnik exception (albeit unlikely that
> something breaks a whole column of tiles).
>
> Bye
> Frederik
>
> --
> Frederik Ramm ## eMail frederik at remote.org ## N49°00'09" E008°23'33"
>
> ______________________________**_________________
> dev mailing list
> dev at openstreetmap.org
> http://lists.openstreetmap.**org/listinfo/dev<http://lists.openstreetmap.org/listinfo/dev>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openstreetmap.org/pipermail/dev/attachments/20120619/65ed747b/attachment-0001.html>
More information about the dev
mailing list