[FEAT] Add logging of timing for total time, each main section and for each tile generation step #225

alfh · 2023-11-04T17:41:28Z

This PR…

Add logging of duration of various steps of the process, to be able to see where the focus for improvements should be, and to be able to detect any changes in performance from version to version, or from machine to machine, or from country to country.

Considerations and implementations

There are a couple of commits at the start of the history which are really general small fixups, I could have created a separate PR for them.

Ended up adding a Timings class for handling the actual duration and generating the text for logging, or doing the actual logging, based on PR comments from @treee111 .

I have just added simple logging, and have not looked for any general "metrics" python library.

Only wall time is logged.
Originally I also included CPU time in most places, but I think the CPU time it less interesting, since it is mainly other processes that are being spawned.
I have not added an CLI option to choose whether you want the logging or not, I assume it is quite interesting for most people.

I have added debug level logging for each tile, to get the duration taken for each tile.

Originally logged the time with 5 decimals, but reduced it to 3, even though that means some steps are shown as taking 0.000 seconds.

I have made one final restructuring of the commits, have kept the main parts of the commit from @treee111 for the PR review, a couple of minor suggestions there I splitted out, and combined with my commits, to have a cleaner commit history, with fewer "correction" commits.

How to test

Run the CLI to generate a tile or a country, and observe the logging of duration. e.g. python -m wahoomc cli -co malta
Run the CLI to generate a tile or a country, and observe the logging of duration. e.g. python -m wahoomc cli -co malta -v
Run the unit tests with "python -m unittest -v" to see the logging.

Pull Request Checklist

Reviewed the Contributing Guidelines
- Especially the Pull-Requests section
Commits (and commit-messages) are understandable
Tested with macOS / Linux
Tested with Windows

alfh · 2023-11-04T18:13:48Z

I see that pylint now complains about too many local variables in merge_splitted_tiles_with_land_and_sea.

Unsure if I should just remove the logging there for now, or if the method should be splitted somehow, but that would be a general refactoring, and not as part of the adding of timings, I think.

treee111

thanks for this big PR!

I added some inline comments, in general I have these comments:

A lot of copy and paste code - we should think of how to avoid that for changes concerning timing later on which should be reflected at all places. In the in-line comment I talked about a class to handle that.
I tried to have a consistent logging for the tiles by outputting the log_tile before doing something to know where it crashed but only one line per "tile" or "tile/country" combination. For easier reporting and understanding logs. The green marked logs are OK for me, there you only added the timing. Lets think of how we can change the second line so that it is better readable and we only have one logging line per "tile" or "tile/country" combination. For all timing-logs maybe use a central logging in the class - see 1. ?

instead of having:

INFO:# Creating .map files for tiles
INFO:+ (tile 1 of 2) Coordinates: 137,100
INFO:+ (tile 1 of 2) Coordinates: 137,100 / took 1.80000
INFO:+ (tile 2 of 2) Coordinates: 138,100
INFO:+ (tile 2 of 2) Coordinates: 138,100 / took 3.23181
INFO:+ Creating .map files for tiles: OK, took 0.04103, 5.03245

that might suit me better:

INFO:# Creating .map files for tiles
INFO:+ (tile 1 of 2) Coordinates: 137,100
INFO:+  took 1.80000 sec.
INFO:+ (tile 2 of 2) Coordinates: 138,100
INFO:+  took 3.23181 sec.
INFO:+ Creating .map files for tiles: OK, took 0.04103, 5.03245

Sometime you output one, sometimes two values. Could we add before/after the value what it represents, i.e. processing secs and CPU secs or other abbreviations more suitable to you?
rebasing onto develop should make all unittests run green.

as said already, thanks for the effort 👍 - I am looking forward to get this further :-)
If you need some ideas concerning my comments, I could bring up my idea also "in code"!

wahoomc/downloader.py

wahoomc/main.py

wahoomc/osm_maps_functions.py

wahoomc/main.py

alfh · 2023-11-05T09:19:35Z

My considerations on the logging style

INFO:+ (tile 1 of 2) Coordinates: 137,100
INFO:+  took 1.80000 sec.

vs

INFO:+ (tile 1 of 2) Coordinates: 137,100
INFO:+ (tile 1 of 2) Coordinates: 137,100 / took 1.80000

is that I wanted to be able to do a "grep" on the log output, and quickly find all tiles that were slow / fast / something else.

But it is also important to log the tile when starting to process it, in case there is some deadlock or something.

I was now considering a "log_tile_start" method, which does not log with a newline, and then a "log_tile_end" which then logs the "took .." section.
But it seems Python has no nice way of achieving that with the log framework.

I also saw that there are decorator pattern, which could possible be used for both the logging of the main tile info, and the duration at the end.

alfh · 2023-11-05T09:52:44Z

I force pushed some updated, before I noticed that you had commented the PR, sorry about that.

Thanks for the feedback, I'll be looking into these wise comments now.

alfh · 2023-11-05T11:17:43Z

Maybe the tile duration could be logged as debug instead of info log level?
So only people really into the details would see it.

Not quite sure who such differences are handled in Python.

- like you wrote by yourself :-) treee111#225 (comment) - plus removing all the calls of start_wall_time throughout the files - log_duration is only called once so cutting down the method makes it clearer and identical to stop_and_return in my opinion - plus painting a "line" before the logging to be cosistent to the other parts of the log

treee111 · 2023-11-05T20:32:55Z

thanks for thinking about outputting the per tile details and giving your thought behind the logging :-)

My considerations on the logging style
INFO:+ (tile 1 of 2) Coordinates: 137,100
INFO:+  took 1.80000 sec.
vs
INFO:+ (tile 1 of 2) Coordinates: 137,100
INFO:+ (tile 1 of 2) Coordinates: 137,100 / took 1.80000
is that I wanted to be able to do a "grep" on the log output, and quickly find all tiles that were slow / fast / something else.

But it is also important to log the tile when starting to process it, in case there is some deadlock or something.

I was now considering a "log_tile_start" method, which does not log with a newline, and then a "log_tile_end" which then logs the "took .." section. But it seems Python has no nice way of achieving that with the log framework.

Yesterday that was also my first thought. Adding "took .." or somehow replacing the whole line with the addition "took .." but that is not possible without hacks as you found out as well.

I also saw that there are decorator pattern, which could possible be used for both the logging of the main tile info, and the duration at the end.

I saw decorators also in another project and thought that they could be used for the timing stuff. Because I have never used them I'm not really sure how that would go and look...

Maybe the tile duration could be logged as debug instead of info log level? So only people really into the details would see it.

Not quite sure who such differences are handled in Python.

Very nice idea - i like! 🥇 That would mean, that all other log.debug messages would be outputted as well, but I think for your grep that would not matter.
Outputting as debug is easy and done in the repo as well. output it with log.debug and call wahooMapsCreator with -v.

treee111

nice collaboration by the way :-)
looking forward to hear from you 👍

I've done three things:

added inline comments
pushed a commit to your branch (clearing up some inline comments already)
addes a comment to the PR

You still might rebase your branch onto latest develop (pull develop first) to integrate our unittest PR 04f09ac. Don't worry about me, I'm confident that my Git will not get confused ;-)

wahoomc/timings.py

wahoomc/osm_maps_functions.py

wahoomc/main.py

wahoomc/downloader.py

- like you wrote by yourself :-) treee111#225 (comment) - plus removing all the calls of start_wall_time throughout the files - log_duration is only called once so cutting down the method makes it clearer and identical to stop_and_return in my opinion - plus painting a "line" before the logging to be cosistent to the other parts of the log

alfh · 2023-11-06T19:55:28Z

@treee111 Rebased onto develop, and adjusted based on your comments.

I want to clean up the commit history somewhat, but ran out of time today, but still wanted to possibly get some comments to the way I added the debug logging for the tile timings.

I ended up not using the debug vs info logging functionality in Timings class, so I might as well remove that.

Unsure how you feel about the log_tile_info and log_tile_debug methods in osm_map_functions.

Getting the debug logging to display using the "cli" works with "-v", but when running the unit tests, that does not currently work is seem like.

treee111 · 2023-11-07T21:01:25Z

@treee111 Rebased onto develop, and adjusted based on your comments.

👍 looks very promising

I want to clean up the commit history somewhat, but ran out of time today, but still wanted to possibly get some comments to the way I added the debug logging for the tile timings.

Due to that we only squash to develop, all commits will get into one anyway so I would be OK as-is now. Having a clean commit history also in PR's is something I also like, so feel free to clean it up if you have some spare time.

I ended up not using the debug vs info logging functionality in Timings class, so I might as well remove that.

If you don't use it remote it, so you can also remove the value from the constructor where you hand it over but do not use it acutally.
If one would use the debug vs. info functionality of Timings, I thought of this in the timings class

then giving the two return values to the log_tile function

but that does not work as we have a tuple now and not two separate parameters.

Could also be achieved but wouldn't work for situations where we do not need the True or False because INFO logging is fixed (could also be achieved but would make it even harder to maintain). Furthermore that would not be easy to read and maintain in my opinion.

Unsure how you feel about the log_tile_info and log_tile_debug methods in osm_map_functions.

I'd rather remove them as written and already committed here: 4468c7e. If you don't agree feel free to remove that commit and we talk about that one more time.
What I really like is your refactoring of log_tile method - nice!

Getting the debug logging to display using the "cli" works with "-v", but when running the unit tests, that does not currently work is seem like.

If I run unittests I normally have no output and do not need any. Do you want to check and compare the timing using unittests?
For which unittest files do you want it to work? For test_generated_files.py you could easy add it to the cli call in my opinion (haven't tried yet):

wahooMapsCreator/tests/test_generated_files.py

Lines 192 to 193 in 199a13e

    
           result = os.system( 
        
               f'python -m wahoomc cli -co {country} -tag tag-wahoo.xml -fp -c -md 9999 -nbc')

- like you wrote by yourself :-) treee111#225 (comment) - log_duration is only called once so cutting down the method makes it clearer and identical to stop_and_return in my opinion - plus painting a "line" before the logging to be cosistent to the other parts of the log

alfh · 2023-11-08T17:34:24Z

This is how the logging looks like now

INFO:--------------------------------------------------------------------------------
INFO:--------------------------------------------------------------------------------
INFO:# check geofabrik.json file
INFO:# Input country: malta.
INFO:--------------------------------------------------------------------------------
INFO:+ Involved country: malta
INFO:--------------------------------------------------------------------------------
INFO:# check land_polygons.shp file
INFO:--------------------------------------------------------------------------------
INFO:# check countries .osm.pbf files
INFO:+ Checking for old maps and remove them
INFO:+ mapfile for malta: up-to-date.
INFO:--------------------------------------------------------------------------------
INFO:# Filter tags from country osm.pbf files
INFO:+ Filtering unwanted map objects out of map of malta
INFO:+ Filter tags from country osm.pbf files: OK, took 1.072 s
INFO:--------------------------------------------------------------------------------
INFO:# Generate land for each coordinate
INFO:+ (tile 1 of 2) Coordinates: 137,100
INFO:+ (tile 2 of 2) Coordinates: 138,100
INFO:+ Generate land for each coordinate: OK, took 0.625 s
INFO:--------------------------------------------------------------------------------
INFO:# Generate sea for each coordinate
INFO:+ (tile 1 of 2) Coordinates: 137,100
INFO:+ (tile 2 of 2) Coordinates: 138,100
INFO:+ Generate sea for each coordinate: OK, took 0.000 s
INFO:--------------------------------------------------------------------------------
INFO:# Split filtered country files to tiles
INFO:+ (tile 1 of 2) Coordinates: 137,100 / malta
INFO:+ (tile 2 of 2) Coordinates: 138,100 / malta
INFO:+ Split filtered country files to tiles: OK, took 2.043 s
INFO:--------------------------------------------------------------------------------
INFO:# Merge splitted tiles with land, elevation, and sea
INFO:+ (tile 1 of 2) Coordinates: 137,100
INFO:+ (tile 2 of 2) Coordinates: 138,100
INFO:+ Merge splitted tiles with land, elevation, and sea: OK, took 1.872 s
INFO:--------------------------------------------------------------------------------
INFO:# Creating .map files for tiles
INFO:+ (tile 1 of 2) Coordinates: 137,100
INFO:+ (tile 2 of 2) Coordinates: 138,100
INFO:+ Creating .map files for tiles: OK, took 2.846 s
INFO:--------------------------------------------------------------------------------
INFO:# Create: .map.lzma files
INFO:+ Country: malta
INFO:+ Copying .map.lzma tiles to output folders
INFO:+ Create .map.lzma files: OK, took 0.001 s
INFO:--------------------------------------------------------------------------------
INFO:# Create: .map files
INFO:+ Country: malta
INFO:+ Copying .map tiles to output folders
INFO:+ Create .map files: OK, took 0.001 s
INFO:--------------------------------------------------------------------------------
INFO:# Total time 8.476 s

When running with verbose, it looks like this (just an excerpt of the log)

INFO:# Generate sea for each coordinate
DEBUG:+ (tile 1 of 8) Coordinates: 122,69 / took 0.000 s
DEBUG:+ (tile 2 of 8) Coordinates: 122,70 / took 0.000 s
DEBUG:+ (tile 3 of 8) Coordinates: 122,71 / took 0.000 s
DEBUG:+ (tile 4 of 8) Coordinates: 122,72 / took 0.000 s
DEBUG:+ (tile 5 of 8) Coordinates: 123,69 / took 0.000 s
DEBUG:+ (tile 6 of 8) Coordinates: 123,70 / took 0.000 s
DEBUG:+ (tile 7 of 8) Coordinates: 123,71 / took 0.000 s
DEBUG:+ (tile 8 of 8) Coordinates: 123,72 / took 0.000 s
INFO:+ Generate sea for each coordinate: OK, took 0.000 s
INFO:--------------------------------------------------------------------------------
INFO:# Split filtered country files to tiles
INFO:+ (tile 1 of 8) Coordinates: 122,69 / faroe-islands
DEBUG:+ (tile 1 of 8) Coordinates: 122,69 / faroe-islands took 0.082 s
INFO:+ (tile 2 of 8) Coordinates: 122,70 / faroe-islands
DEBUG:+ (tile 2 of 8) Coordinates: 122,70 / faroe-islands took 0.555 s
INFO:+ (tile 3 of 8) Coordinates: 122,71 / faroe-islands
DEBUG:+ (tile 3 of 8) Coordinates: 122,71 / faroe-islands took 0.952 s
INFO:+ (tile 4 of 8) Coordinates: 122,72 / faroe-islands
DEBUG:+ (tile 4 of 8) Coordinates: 122,72 / faroe-islands took 0.097 s
INFO:+ (tile 5 of 8) Coordinates: 123,69 / faroe-islands
DEBUG:+ (tile 5 of 8) Coordinates: 123,69 / faroe-islands took 0.088 s
INFO:+ (tile 6 of 8) Coordinates: 123,70 / faroe-islands
DEBUG:+ (tile 6 of 8) Coordinates: 123,70 / faroe-islands took 0.796 s
INFO:+ (tile 7 of 8) Coordinates: 123,71 / faroe-islands
DEBUG:+ (tile 7 of 8) Coordinates: 123,71 / faroe-islands took 1.480 s
INFO:+ (tile 8 of 8) Coordinates: 123,72 / faroe-islands
DEBUG:+ (tile 8 of 8) Coordinates: 123,72 / faroe-islands took 0.508 s
INFO:+ Split filtered country files to tiles: OK, took 4.559 s
INFO:--------------------------------------------------------------------------------
INFO:# Merge splitted tiles with land, elevation, and sea
INFO:+ (tile 1 of 8) Coordinates: 122,69
DEBUG:--------------------------------------------------------------------------------
DEBUG:# Sorting land* osm files
DEBUG:+ Sorting land* osm files: OK
DEBUG:+ (tile 1 of 8) Coordinates: 122,69 / took 0.375 s
INFO:+ (tile 2 of 8) Coordinates: 122,70
DEBUG:--------------------------------------------------------------------------------
DEBUG:# Sorting land* osm files
DEBUG:+ Sorting land* osm files: OK
DEBUG:+ (tile 2 of 8) Coordinates: 122,70 / took 0.815 s
INFO:+ (tile 3 of 8) Coordinates: 122,71

Note that there is a bit excessive logging about the sorting, where three lines appear for each tile about sorting. That is "as-is", I will probably raise a PR to get rid of that, and only keep one line per tile about sorting

alfh · 2023-11-08T17:35:53Z

@treee111 I consider the PR ready for final review now, I currently do not know of anything outstanding.

Use the introduced method for a consistent loggging of which tile is being processed, also for the elevation generation, seems like it was forgotten to update that when the new method was introduced.

Include only wall time, since the CPU usage of the Python code is neglible, since it mainly spawns other processes.

Include only wall time.

Only include the wall time used.

…_tiles_with_land_and_sea method

- like you wrote by yourself :-) treee111#225 (comment) - log_duration is only called once so cutting down the method makes it clearer and identical to stop_and_return in my opinion - plus painting a "line" before the logging to be cosistent to the other parts of the log

treee111 · 2023-11-09T16:21:01Z

Unsure how you feel about the log_tile_info and log_tile_debug methods in osm_map_functions.

I'd rather remove them as written and already committed here: 4468c7e. If you don't agree feel free to remove that commit and we talk about that one more time. What I really like is your refactoring of log_tile method - nice!

@alfh what do you think of my described change? You lost my commit in your current branch, restored it from my local repo here:
4468c7e

other than that I am with you and will approve this PR

alfh · 2023-11-09T17:33:56Z

Yes, sorry I missed that commit, noticed it afterwards. I want to have it quite visible when reading code if logging goes to info or debug. So I prefer log_tile_info and log_tile_debug, and do not mind the "overhead" of two extra method. It also means pylint will not complain about too many parameters. But it is probably mainly a code style taste. I am OK with both approaches. Alf ⁣Få BlueMail for Android 9. nov. 2023, 17:21 kl. 17:21 skrev "Benjamin K." ***@***.***>:

…

> > Unsure how you feel about the log_tile_info and log_tile_debug methods in osm_map_functions. > > I'd rather remove them as written and already committed here: [4468c7e](4468c7e). If you don't agree feel free to remove that commit and we talk about that one more time. What I really like is your refactoring of `log_tile` method - nice! > @alfh what do you think of my described change? You lost my commit in your current branch, restored it from my local repo here: 4468c7e other than that I am with you and will approve this PR -- Reply to this email directly or view it on GitHub: #225 (comment) You are receiving this because you were mentioned. Message ID: ***@***.***>

treee111

Yes, sorry I missed that commit, noticed it afterwards. I want to have it quite visible when reading code if logging goes to info or debug. So I prefer log_tile_info and log_tile_debug, and do not mind the "overhead" of two extra method. It also means pylint will not complain about too many parameters. But it is probably mainly a code style taste. I am OK with both approaches.

alright, so I am also OK with having it more visible what the debug level is.
I olny waht to make sure the comment doesn't get lost.

Let's get this merged! Thanks a lot 👍

alfh force-pushed the add-timins-logging branch from 10e12fc to 0562cc8 Compare November 4, 2023 18:07

treee111 requested changes Nov 4, 2023

View reviewed changes

alfh force-pushed the add-timins-logging branch 2 times, most recently from 0562cc8 to 4b94c2b Compare November 5, 2023 09:42

treee111 force-pushed the add-timins-logging branch from ff54dac to f965cc2 Compare November 5, 2023 20:21

treee111 requested changes Nov 5, 2023

View reviewed changes

wahoomc/timings.py Outdated Show resolved Hide resolved

wahoomc/timings.py Outdated Show resolved Hide resolved

wahoomc/osm_maps_functions.py Outdated Show resolved Hide resolved

wahoomc/main.py Outdated Show resolved Hide resolved

wahoomc/downloader.py Outdated Show resolved Hide resolved

alfh force-pushed the add-timins-logging branch from f965cc2 to 6bbb5d8 Compare November 6, 2023 19:52

alfh force-pushed the add-timins-logging branch from 4468c7e to a852665 Compare November 8, 2023 17:17

alfh and others added 9 commits November 8, 2023 18:39

Fix spelling mistake in comments and logging

fb618d2

Use self.log_tile for elevation generation logging

f84a774

Use the introduced method for a consistent loggging of which tile is being processed, also for the elevation generation, seems like it was forgotten to update that when the new method was introduced.

Add logging of total time taken for the generation

3c5ef37

Include only wall time, since the CPU usage of the Python code is neglible, since it mainly spawns other processes.

Add logging of time taken for each main part of the process

9f913c9

Include only wall time.

Add logging of duration per tile generation operation

a934d40

Only include the wall time used.

Disable pylint warn about too many local variables for merge_splitted…

408ee8c

…_tiles_with_land_and_sea method

Fix logging in main to include # at the start

a76898f

Add new Timings class for logging duration

db398e6

alfh and others added 8 commits November 8, 2023 18:39

Use Timings class for logging total duration in main

57ecd54

Use Timings class for logging in downloader

6d30edd

Use Timings class for logging in main sections

113606e

Use Timings class for logging for tile logging

e51a9f3

Move tile timings logging to debug log level

8b1a57b

Remove code duplication in log_tile method

b9ba1cc

Use three decimal digits when logging duration

5fa9011

Reduce text duplication in Timings class

6c4b260

alfh force-pushed the add-timins-logging branch from 555c731 to 6c4b260 Compare November 8, 2023 17:39

alfh requested a review from treee111 November 8, 2023 17:40

treee111 approved these changes Nov 9, 2023

View reviewed changes

treee111 changed the title ~~Add logging of timing for total time, for each main section, and for each tile generation step~~ [FEAT] Add logging of timing for total time, each main section and for each tile generation step Nov 9, 2023

treee111 added the enhancement New feature or request label Nov 9, 2023

treee111 merged commit e5baae0 into treee111:develop Nov 9, 2023
2 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[FEAT] Add logging of timing for total time, each main section and for each tile generation step #225

[FEAT] Add logging of timing for total time, each main section and for each tile generation step #225

alfh commented Nov 4, 2023 •

edited by treee111

Loading

alfh commented Nov 4, 2023

treee111 left a comment

alfh commented Nov 5, 2023

alfh commented Nov 5, 2023

alfh commented Nov 5, 2023

treee111 commented Nov 5, 2023

treee111 left a comment

alfh commented Nov 6, 2023

treee111 commented Nov 7, 2023

alfh commented Nov 8, 2023

alfh commented Nov 8, 2023

treee111 commented Nov 9, 2023

alfh commented Nov 9, 2023 via email

treee111 left a comment

[FEAT] Add logging of timing for total time, each main section and for each tile generation step #225

[FEAT] Add logging of timing for total time, each main section and for each tile generation step #225

Conversation

alfh commented Nov 4, 2023 • edited by treee111 Loading

This PR…

Considerations and implementations

How to test

Pull Request Checklist

alfh commented Nov 4, 2023

treee111 left a comment

Choose a reason for hiding this comment

alfh commented Nov 5, 2023

alfh commented Nov 5, 2023

alfh commented Nov 5, 2023

treee111 commented Nov 5, 2023

treee111 left a comment

Choose a reason for hiding this comment

alfh commented Nov 6, 2023

treee111 commented Nov 7, 2023

alfh commented Nov 8, 2023

alfh commented Nov 8, 2023

treee111 commented Nov 9, 2023

alfh commented Nov 9, 2023 via email

treee111 left a comment

Choose a reason for hiding this comment

alfh commented Nov 4, 2023 •

edited by treee111

Loading