search

treee111 / wahooMapsCreator

Create maps for Wahoo device based on latest OSM maps
247 stars 25 forks source link

Freeze on creating .map files for tiles (1/52) #205

Closed code-XmR closed 1 year ago

code-XmR commented 1 year ago

Expected Behavior

Probably create a map ;)

Current Behavior

Hangs on "Creating .map files for tiles (tile 1 of 52) Coordinates: 137,81". The first time I waited about 15 minutes, then restarted the whole process and waited 2h without progress.

Steps to Reproduce the Issue

  1. Using GUI start creating map for Poland with only one change in advanced to create map for cruiser (same problem without this option enabled)

Context

Log Output / Stack Trace

{...}
treee111 commented 1 year ago

Hi @code-XmR, thanks for writing the issue! 👍

Could you please add some more information:

That helps to narrow down the issue

code-XmR commented 1 year ago

I will update this later with more information, for now I have:

WangONC commented 1 year ago

I seem to have the same problem and will stop at INFO: # Creating. map files for tiles. The logs near here look like this. I have run them multiple times, each time stopping at this process, but the progress is different

INFO:+ (tile 25 of 786) Coordinates: 183,103

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:06 ÏÂÎç org.openstreetmap.osmosis.core.Osmosis run'

DEBUG:subprocess:' Ð ÅÏ¢: Osmosis Version 0.48.3'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:06 ÏÂÎç org.openstreetmap.osmosis.core.Osmosis run'

DEBUG:subprocess:' Ð ÅÏ¢: Preparing pipeline.'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:06 ÏÂÎç org.mapsforge.map.writer.osmosis.MapFileWriterTask '

DEBUG:subprocess:' Ð ÅÏ¢: mapfile-writer version: mapsforge-map-writer-0.18.0'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:06 ÏÂÎç org.mapsforge.map.writer.osmosis.MapFileWriterTask '

DEBUG:subprocess:' Ð ÅÏ¢: mapfile format specification version: 3'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:06 ÏÂÎç org.openstreetmap.osmosis.core.Osmosis run'

DEBUG:subprocess:' Ð ÅÏ¢: Launching pipeline execution.'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:06 ÏÂÎç org.openstreetmap.osmosis.core.Osmosis run'

DEBUG:subprocess:' Ð ÅÏ¢: Pipeline executing, waiting for completion.'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:06 ÏÂÎç org.mapsforge.map.writer.osmosis.MapFileWriterTask process'

DEBUG:subprocess:' Ð ÅÏ¢: start reading data...'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:06 ÏÂÎç org.mapsforge.map.writer.osmosis.MapFileWriterTask complete'

DEBUG:subprocess:' Ð ÅÏ¢: completing read...'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:06 ÏÂÎç org.mapsforge.map.writer.RAMTileBasedDataProcessor complete'

DEBUG:subprocess:' Ð ÅÏ¢: handle relations...'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:07 ÏÂÎç org.mapsforge.map.writer.RAMTileBasedDataProcessor complete'

DEBUG:subprocess:' Ð ÅÏ¢: handle ways...'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:07 ÏÂÎç org.mapsforge.map.writer.osmosis.MapFileWriterTask complete'

DEBUG:subprocess:' Ð ÅÏ¢: start writing file...'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter writeSubfile'

DEBUG:subprocess:' Ð ÅÏ¢: written 10% of sub file for zoom interval 1 (10,0,17)'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter writeSubfile'

DEBUG:subprocess:' Ð ÅÏ¢: written 20% of sub file for zoom interval 1 (10,0,17)'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter writeSubfile'

DEBUG:subprocess:' Ð ÅÏ¢: written 30% of sub file for zoom interval 1 (10,0,17)'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter writeSubfile'

DEBUG:subprocess:' Ð ÅÏ¢: written 40% of sub file for zoom interval 1 (10,0,17)'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter writeSubfile'

DEBUG:subprocess:' Ð ÅÏ¢: written 50% of sub file for zoom interval 1 (10,0,17)'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter$WayPreprocessingCallable call'

DEBUG:subprocess:' Ð ÅÏ¢: Large geometry 32951623373 (3219 coords, down from 11851 coords)'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter writeSubfile'

DEBUG:subprocess:' Ð ÅÏ¢: written 60% of sub file for zoom interval 1 (10,0,17)'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter writeSubfile'

DEBUG:subprocess:' Ð ÅÏ¢: written 70% of sub file for zoom interval 1 (10,0,17)'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter writeSubfile'

DEBUG:subprocess:' Ð ÅÏ¢: written 80% of sub file for zoom interval 1 (10,0,17)'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter writeFile'

DEBUG:subprocess:' Ð ÅÏ¢: JTS Geometry cache hit rate: 1.0'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter writeFile'

DEBUG:subprocess:' Ð ÅÏ¢: JTS Geometry total load time: 0'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.MapFileWriter writeFile'

DEBUG:subprocess:' Ð ÅÏ¢: Finished writing file.'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.osmosis.MapFileWriterTask complete'

DEBUG:subprocess:' Ð ÅÏ¢: finished...'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.mapsforge.map.writer.osmosis.MapFileWriterTask complete'

DEBUG:subprocess:' Ð ÅÏ¢: estimated memory consumption: 132.91MB'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.openstreetmap.osmosis.core.Osmosis run'

DEBUG:subprocess:' Ð ÅÏ¢: Pipeline complete.'

DEBUG:subprocess:'5ÔÂ 16, 2023 9:53:08 ÏÂÎç org.openstreetmap.osmosis.core.Osmosis run'

DEBUG:subprocess:' Ð ÅÏ¢: Total execution time: 2755 milliseconds.'

DEBUG:subprocess:''

DEBUG:subprocess:'LZMA 19.00 (x86) : Igor Pavlov : Public domain : 2019-02-21'

DEBUG:subprocess:''

DEBUG:subprocess:'Input size: 364065 (0 MiB)'

DEBUG:subprocess:'\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08\x08 \x08\x08\x08\x08\x08\x08\x08\ INFO:+ (tile 26 of 786) Coordinates: 183,104

treee111 commented 1 year ago

I will update this later with more information, for now I have:

* conda list: https://pastebin.com/5fekFsnc

* creating Malta via GUI was successful

* creating Poland via GUI failed
  There is nothing from debug about this, and debug was working before, I paste some here:

mhmm that is strange. If Malta worked, it should also work for Poland... conda list looks good. If there is no output after this, it seams there is no error because an error will be printed as well.

INFO:+ (tile 1 of 52) Coordinates: 137,81

I could build a alpha version which loggs even more so that we can fin out the not working part step-by-step.

treee111 commented 1 year ago

I seem to have the same problem and will stop at INFO: # Creating. map files for tiles. The logs near here look like this. I have run them multiple times, each time stopping at this process, but the progress is different

Have you tried this already? https://github.com/treee111/wahooMapsCreator/blob/develop/docs/FAQ.md#i-have-a-java-error-java-heap-space---out-of-memory

Could you please add some more information:

WangONC commented 1 year ago

I seem to have the same problem and will stop at INFO: # Creating. map files for tiles. The logs near here look like this. I have run them multiple times, each time stopping at this process, but the progress is different

Have you tried this already? https://github.com/treee111/wahooMapsCreator/blob/develop/docs/FAQ.md#i-have-a-java-error-java-heap-space---out-of-memory

Could you please add some more information:

  • what is the output if you call conda list inside your Anaconda environment?
  • does generate maps for a small country work? E.g. europe/malta choosen via GUI or via CLI python -m wahoomc cli -co malta

conda list: https://pastebin.com/Ecsn2wbr

Due to the normal use of version 3.2.0, I have switched back to version 3.2.0 for wahoomc, and the other packages remain unchanged

I have previously attempted to execute python - m wahoomc cli co malta con srtm1- v, but it also stopped halfway through the execution without any resource usage in the background and no updated output in the logs.

alfh commented 1 year ago

I also see hangs in similar ways, have seen it mainly when generating for Norway, which has about 1200 tiles. It seems random which tiles causes the hang. I will modify wahoomc, so that it starts java with "garbage collection" logs, since that will allow one to see if a lot of garbage collection happens, but I do not think so, since CPU usage is low.

I did perform a "jstack" command, to get the thread dump, on one of the hangs, I will attach that log tomorrow if I have time. I will also check if wahoomc is using the latest version of the "mapwriter" plugin, I saw that it is actively maintained. The osmosis tool is apparently not actively developed.

I also plan on do just use a bash shell, to invoke the same "tile convert command using osmosis" a 100 times, to see if that provokes the hang in an iteration.

I suspect it is some kind of deadlock.

alfh commented 1 year ago

Some progress today. Twice I have gotten a hang on the same tile, while generating norway.

This is the one it hangs on INFO:+ (tile 415 of 1176) Coordinates: 133,75

I'll now create a bash loop script, to see how often this tile causes a hang.

Garbage collection is not the issue, since the gc.log was not showing any major collections. I had also enabled the Xlog for os, this gave this at the end [2023-05-27T08:44:12.590+0000][23989ms][info][os,thread] JavaThread exiting (tid: 197022). [2023-05-27T08:44:12.590+0000][23989ms][info][os,thread] Thread finished (tid: 197022, pthread id: 139806134847040). [2023-05-27T08:44:17.590+0000][28988ms][info][os,thread] JavaThread exiting (tid: 197082). [2023-05-27T08:44:17.590+0000][28988ms][info][os,thread] Thread finished (tid: 197082, pthread id: 139806102218304). [2023-05-27T08:44:22.590+0000][33988ms][info][os,thread] JavaThread exiting (tid: 197080). [2023-05-27T08:44:22.590+0000][33988ms][info][os,thread] Thread finished (tid: 197080, pthread id: 139806104315456). [2023-05-27T09:10:58.729+0000][1630127ms][info][os,thread] Thread "Unknown thread" started (pthread id: 139806104315456, attributes: stacksize: 1024k, guardsize: 0k, detached). [2023-05-27T09:10:58.729+0000][1630127ms][info][os,thread] Thread is alive (tid: 197751, pthread id: 139806104315456).

Note the long delay from 08:44 to 09:10

I waited another 30 minutes before doing a "Ctrl+C"

The first attempt at just running this tile from commandline directly, did not cause a hang, it took about 25 seconds.

THis is output from that execution with time command INFO: Total execution time: 24118 milliseconds. Command being timed: "java -Xlog:gc=debug:file=/dev/shm/gc.log:time,uptimemillis,pid -Xlog:os=info:file=/dev/shm/javalog:time,uptimemillis,level,tags -cp /home/linuxbrew/.linuxbrew/Cellar/osmosis/0.48.3/libexec/lib/default/plexus-classworlds-2.5.2.jar -Dapp.home=/home/linuxbrew/.linuxbrew/Cellar/osmosis/0.48.3/libexec -Dclassworlds.conf=/home/linuxbrew/.linuxbrew/Cellar/osmosis/0.48.3/libexec/config/plexus.conf org.codehaus.classworlds.Launcher --rb /home/alf/wahooMapsCreatorData/_tiles/133/75/merged.osm.pbf --mw file=/home/alf/wahooMapsCreatorData/_tiles/133/75.map bbox=58.813742,7.031250,59.534318,8.437500 zoom-interval-conf=10,0,17 threads=21 tag-conf-file=/home/alf/wahooMapsCreatorData/_config/tag_wahoo_adjusted/tag-wahoo-poi.xml" User time (seconds): 93.63 System time (seconds): 1.86 Percent of CPU this job got: 394% Elapsed (wall clock) time (h:mm:ss or m:ss): 0:24.20 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 4534364 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 12 Minor (reclaiming a frame) page faults: 100619 Voluntary context switches: 37382 Involuntary context switches: 4208 Swaps: 0 File system inputs: 0 File system outputs: 96 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0

alfh commented 1 year ago

I now think it is more likely that this is something in the communication between python and the osmosis/java command.

Since when I ran the java commandline 10 times directly from commandline, I saw no problems. But as soon as I invoke "python -m wahoomc cli -co norway -nbc -z" (with modified main.py, to be able to skip directly to the "creating .map files" section) I again get a hang on INFO:+ (tile 414 of 1176) Coordinates: 133,74 / took 28.39613 INFO:+ (tile 415 of 1176) Coordinates: 133,75

I wonder if it can be caused by massive output from the java command to std out, and how python is processing it.

diff --git a/wahoomc/main.py b/wahoomc/main.py
index 635bb7f..220a8ad 100644
--- a/wahoomc/main.py
+++ b/wahoomc/main.py
@@ -77,24 +77,24 @@ def run(run_level):
         o_osm_maps = OsmMaps(o_osm_data)

         # Filter tags from country osm.pbf files'
-        o_osm_maps.filter_tags_from_country_osm_pbf_files()
+#        o_osm_maps.filter_tags_from_country_osm_pbf_files()

         # Generate land
-        o_osm_maps.generate_land()
+#        o_osm_maps.generate_land()

         # Generate sea
-        o_osm_maps.generate_sea()
+#        o_osm_maps.generate_sea()

         # Generate elevation
         if o_input_data.contour:
             o_osm_maps.generate_elevation(o_input_data.use_srtm1)

         # Split filtered country files to tiles
-        o_osm_maps.split_filtered_country_files_to_tiles()
+#        o_osm_maps.split_filtered_country_files_to_tiles()

         # Merge splitted tiles with land and sea
-        o_osm_maps.merge_splitted_tiles_with_land_and_sea(
-            o_input_data.process_border_countries)
+#        o_osm_maps.merge_splitted_tiles_with_land_and_sea(
+#            o_input_data.process_border_countries)

Likely this problem https://stackoverflow.com/questions/39477003/python-subprocess-popen-hanging

alfh commented 1 year ago

Now fully reproducable with python -m wahoomc cli -xy 133/75 -nbc -z

This naive fix causes it to not hang, but causes

diff --git a/wahoomc/osm_maps_functions.py b/wahoomc/osm_maps_functions.py
index c282c54..659d423 100644
--- a/wahoomc/osm_maps_functions.py
+++ b/wahoomc/osm_maps_functions.py
@@ -47,6 +47,7 @@ def run_subprocess_and_log_output(cmd, error_message, cwd=""):
         process = subprocess.Popen(  # pylint: disable=consider-using-with
             cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, cwd=cwd)

+    process.communicate()
     if error_message and process.wait() != 0:  # 0 means success
         for line in iter(process.stdout.readline, b''):  # b'\n'-separated lines
             # print(line.rstrip())

the following exception once the osmosis is done

INFO:+ (tile 1 of 1) Coordinates: 133,75
Traceback (most recent call last):
  File "/home/alf/anaconda3/envs/gdal-dev/lib/python3.10/runpy.py", line 196, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/home/alf/anaconda3/envs/gdal-dev/lib/python3.10/runpy.py", line 86, in _run_code
    exec(code, run_globals)
  File "/home/alf/github/wahooMapsCreator/wahoomc/__main__.py", line 7, in <module>
    main.run("run")
  File "/home/alf/github/wahooMapsCreator/wahoomc/main.py", line 100, in run
    o_osm_maps.create_map_files(o_input_data.save_cruiser,
  File "/home/alf/github/wahooMapsCreator/wahoomc/osm_maps_functions.py", line 826, in create_map_files
    run_subprocess_and_log_output(
  File "/home/alf/github/wahooMapsCreator/wahoomc/osm_maps_functions.py", line 63, in run_subprocess_and_log_output
    for line in iter(process.stdout.readline, b''):  # b'\n'-separated lines
ValueError: readline of closed file

So need some more Python knowledge, to properly start the subprocess, wait for it to return, and then parse the output

alfh commented 1 year ago

This change fixes the bug, i.e. the 133/75 tile can now be made into a .map file, and all of Norway works fine. But I'm not a Python expert, so it should be improved. Unsure if it is safe to just use/assume utf-8 encoding always.

And the output that is parsed and logged, is all on one line, although Python doc says it should be seprated by newline, and I also see that it is being logged as having newline, it is probably my basic Python knowledge that is not sufficient. (See now that it is probably %r vs %s)

Also unsure if the piping that was used by the code earlier, is needed for something else than getting the output.

diff --git a/wahoomc/osm_maps_functions.py b/wahoomc/osm_maps_functions.py
index c282c54..a0cf2de 100644
--- a/wahoomc/osm_maps_functions.py
+++ b/wahoomc/osm_maps_functions.py
@@ -41,30 +41,23 @@ def run_subprocess_and_log_output(cmd, error_message, cwd=""):
     run given cmd-subprocess and issue error message if wished
     """
     if not cwd:
-        process = subprocess.Popen(
-            cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
+        process = subprocess.run(
+            cmd, capture_output=True, text=True, encoding="utf-8")
     else:
-        process = subprocess.Popen(  # pylint: disable=consider-using-with
-            cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, cwd=cwd)
+        process = subprocess.run(  # pylint: disable=consider-using-with
+            cmd, capture_output=True, cwd=cwd, text=True, encoding="utf-8")

-    if error_message and process.wait() != 0:  # 0 means success
-        for line in iter(process.stdout.readline, b''):  # b'\n'-separated lines
-            # print(line.rstrip())
-            try:
-                log.error('subprocess:%r', line.decode("utf-8").strip())
-            except UnicodeDecodeError:
-                log.error('subprocess:%r', line.decode("latin-1").strip())
+    if error_message and process.returncode != 0:  # 0 means success
+        line = process.stderr
+        log.error('subprocess:%r', line)

         log.error(error_message)
         sys.exit()

     else:
-        for line in iter(process.stdout.readline, b''):  # b'\n'-separated lines
+        line = process.stdout  # b'\n'-separated lines
             # print(line.rstrip())
-            try:
-                log.debug('subprocess:%r', line.decode("utf-8").strip())
-            except UnicodeDecodeError:
-                log.debug('subprocess:%r', line.decode("latin-1").strip())
+        log.debug('subprocess:%r', line)
alfh commented 1 year ago

I've create a PR https://github.com/treee111/wahooMapsCreator/pull/208 for this

treee111 commented 1 year ago

Hi guys, sorry for the delay I was on a bike trip and had some busy times afterwards.

@alfh you are a genious 🥇 ! I would not be so fast in getting this issue nailed down to the Python line(s) that is causing it, very, very nice! 👍

For the time until this is officially release, I made an alpha version for @WangONC and @code-XmR to tryout: 4.0.3a0 install it via pip install wahoomc==4.0.3a0 Would be nice if you could try that out to check if the fix of #208 works for you as well!

Thanks you all for providing so much input! I am still wondering why this came up now and not earlier... @WangONC: Did version 3.2.0 work for you and had no freeze like version 4.0.0 / 4.0.2? That information would help me.

WangONC commented 1 year ago

yes, version 3.2.0 works for me. i made a latest map for my wahoo.

treee111 commented 1 year ago

yes, version 3.2.0 works for me. i made a latest map for my wahoo.

thanks for the reply. So it is most probably caused by this PR #195 in this commit https://github.com/treee111/wahooMapsCreator/pull/195/commits/dd662e1106b828a16de205b5c56170566f1af093 which was shipped with v0.4.0.

Did you test the alpha version I mentioned locally on your computer for your required country / xy-coordinate?

WangONC commented 1 year ago

I have tried version 4.0.3a0 and it successfully created a map of Malta for me. However, I don't seem to see contour lines on the map.

treee111 commented 1 year ago

thanks for checking! Nice that it run through :-)

you might use this theme: https://github.com/treee111/wahooDeviceThemes/tree/link-themes/VTM/masc4ii The theme I have in this repo is not 100% perfect for all devices (focussed on BOLTv1).

A good step would be to check in cruiser if the contour lines are displayed. Create the maps with -c for malta or a xy-combination as example and follow this docu: https://github.com/treee111/wahooMapsCreator/blob/develop/docs/USAGE_CRUISER.md#usage-of-cruiser

treee111 commented 1 year ago

fixed by #208