$ svn update osmarender6/osmarender.xsl At revision 5086. $ svn diff Index: tahlib.pm =================================================================== --- tahlib.pm (revision 5084) +++ tahlib.pm (working copy) @@ -1,4 +1,5 @@ use strict; +use Time::HiRes; # ===================================================================== # The following is duplicated from tilesGen.pl @@ -154,7 +155,11 @@ } my $ErrorFile = $Config{WorkingDirectory}."/".$mainPID.".stderr"; + if ($Config{DebugCommands}) { print "\nStarting $cmd\n" } + my $start_time = Time::HiRes::time(); my $retval = system("$cmd 2> $ErrorFile"); + my $end_time = Time::HiRes::time(); + if ($Config{DebugCommands}) { printf("\n%f seconds: $cmd\n", $end_time - $start_time); } my $ok = 0; my $ExtraInfo = "\nAdditional info about the Error(s):\n"; $ time perl tilesGen.pl xy 2331 1185 > timing.log real 37m38.799s user 35m39.090s sys 0m42.615s $ grep seconds: timing.log | perl -e 'while(<>) { split; $f += $_[0]; } print "$f\n";' 2204.866289 $ grep seconds: timing.log | grep xmlstarlet | perl -e 'while(<>) { split; $f += $_[0]; } print "$f\n";' 563.428417 $ grep seconds: timing.log | grep inkscape | perl -e 'while(<>) { split; $f += $_[0]; } print "$f\n";' 1344.503186 $ grep seconds: timing.log | grep pngcrush | perl -e 'while(<>) { split; $f += $_[0]; } print "$f\n";' 182.490025 $ grep seconds: timing.log | grep -vE "(xmlstarlet|pngcrush|inkscape)" | perl -e 'while(<>) { split; $f += $_[0]; } print "$f\n";' 114.444661 $ grep seconds: timing.log | grep xmlstarlet |sort -n 1.458586 seconds: nice -n10 "xmlstarlet" tr maplint/lib/convert-to-tags.xsl tmp.14107 > "data-14107-maplint.osm" 2.150072 seconds: nice -n10 "xmlstarlet" tr maplint/lib/run-tests.xsl data-14107.osm > "tmp.14107" 14.555764 seconds: nice -n10 "xmlstarlet" tr osmarender6/osmarender.xsl map-features-14107.xml > "/tmp/output-14107-z15.svg-temp.svg" 14.692469 seconds: nice -n10 "xmlstarlet" tr osmarender6/osmarender.xsl map-features-14107.xml > "/tmp/output-14107-z16.svg-temp.svg" 14.753582 seconds: nice -n10 "xmlstarlet" tr osmarender6/osmarender.xsl map-features-14107.xml > "/tmp/output-14107-z14.svg-temp.svg" 14.928225 seconds: nice -n10 "xmlstarlet" tr osmarender6/osmarender.xsl map-features-14107.xml > "/tmp/output-14107-z13.svg-temp.svg" 14.952523 seconds: nice -n10 "xmlstarlet" tr osmarender6/osmarender.xsl map-features-14107.xml > "/tmp/output-14107-z12.svg-temp.svg" 34.085379 seconds: nice -n10 "xmlstarlet" tr osmarender6/osmarender.xsl map-features-14107.xml > "/tmp/output-14107-z12.svg-temp.svg" 39.022808 seconds: nice -n10 "xmlstarlet" tr osmarender6/osmarender.xsl map-features-14107.xml > "/tmp/output-14107-z13.svg-temp.svg" 43.884841 seconds: nice -n10 "xmlstarlet" tr osmarender6/osmarender.xsl map-features-14107.xml > "/tmp/output-14107-z15.svg-temp.svg" 44.807720 seconds: nice -n10 "xmlstarlet" tr osmarender6/osmarender.xsl map-features-14107.xml > "/tmp/output-14107-z14.svg-temp.svg" 150.956584 seconds: nice -n10 "xmlstarlet" tr osmarender6/osmarender.xsl map-features-14107.xml > "/tmp/output-14107-z16.svg-temp.svg" 173.179864 seconds: nice -n10 "xmlstarlet" tr osmarender6/osmarender.xsl map-features-14107.xml > "/tmp/output-14107-z17.svg-temp.svg" $ grep seconds: timing.log | grep xmlstarlet | wc -l 13 $ grep seconds: timing.log | grep inkscape | sort -n | head -1 2.081661 seconds: LC_ALL=C nice -n10 "inkscape" -z -w 1024 -h 256 --export-area=0.000000:656.771665:878.910000:875.695554 --export-png="/tmp/14107.png_part" "/tmp/output-14107-z14.svg" > /tmp/14107.stdout $ grep seconds: timing.log | grep inkscape | sort -n | tail -1 26.373338 seconds: LC_ALL=C nice -n10 "inkscape" -z -w 8192 -h 256 --export-area=0.000000:301.020347:878.910000:328.385833 --export-png="/tmp/14107.png_part" "/tmp/output-14107-z17.svg" > /tmp/14107.stdout $ grep seconds: timing.log | grep inkscape | wc -l 94 $ grep seconds: timing.log | grep pngcrush |sort -n|head -1 0.055027 seconds: nice -n10 pngcrush -q /tmp/tile_12_2331_1185.tmpdir/tile_17_74603_37935.png.cut /tmp/tile_12_2331_1185.tmpdir/tile_17_74603_37935.png >/dev/null $ grep seconds: timing.log | grep pngcrush |sort -n|tail -1 0.387098 seconds: nice -n10 pngcrush -q /tmp/tile_12_2331_1185.tmpdir/tile_13_4663_2371.png.cut /tmp/tile_12_2331_1185.tmpdir/tile_13_4663_2371.png >/dev/null $ grep seconds: timing.log | grep pngcrush | wc -l 1361 $ grep seconds: timing.log | grep -vE "(xmlstarlet|pngcrush|inkscape)" | sort -n 0.569552 seconds: nice -n10 perl attribution.pl < data-14107-frollo-close-areas.osm > data-14107-frollo-close-areas-attribution.osm 1.227420 seconds: nice -n10 perl close-areas.pl 2331 1185 12 < data-14107-frollo.osm > data-14107-frollo-close-areas.osm 9.743237 seconds: nice -n10 perl ./lines2curves.pl /tmp/output-14107-z16.svg-temp.svg > /tmp/output-14107-z16.svg 9.847487 seconds: nice -n10 perl ./lines2curves.pl /tmp/output-14107-z17.svg-temp.svg > /tmp/output-14107-z17.svg 9.867272 seconds: nice -n10 perl ./lines2curves.pl /tmp/output-14107-z15.svg-temp.svg > /tmp/output-14107-z15.svg 9.903871 seconds: nice -n10 perl ./lines2curves.pl /tmp/output-14107-z12.svg-temp.svg > /tmp/output-14107-z12.svg 9.926749 seconds: nice -n10 perl ./lines2curves.pl /tmp/output-14107-z14.svg-temp.svg > /tmp/output-14107-z14.svg 9.927420 seconds: nice -n10 perl ./lines2curves.pl /tmp/output-14107-z13.svg-temp.svg > /tmp/output-14107-z13.svg 10.607178 seconds: nice -n10 perl ./lines2curves.pl /tmp/output-14107-z12.svg-temp.svg > /tmp/output-14107-z12.svg 10.618900 seconds: nice -n10 perl ./lines2curves.pl /tmp/output-14107-z16.svg-temp.svg > /tmp/output-14107-z16.svg 10.708842 seconds: nice -n10 perl ./lines2curves.pl /tmp/output-14107-z14.svg-temp.svg > /tmp/output-14107-z14.svg 10.743964 seconds: nice -n10 perl ./lines2curves.pl /tmp/output-14107-z15.svg-temp.svg > /tmp/output-14107-z15.svg 10.752769 seconds: nice -n10 perl ./lines2curves.pl /tmp/output-14107-z13.svg-temp.svg > /tmp/output-14107-z13.svg