remove per-feature logging to improve performance issue#685

[snowman2]

I saw the issue #685, and so I took a stab at it based on the discussion to see if I could help move things forward.

I commented out the debug print statements instead of deleting them so that you don't have to re-create them when you are debugging (and an official decision on what to do with them has not been reached as far as I know). However, that presents the danger of being re-introduced by accident when committing changes after debugging.

Using this example:

from itertools import chain, repeat
import fiona
def test_to_file():
    with fiona.Env(),fiona.open("../tests/data/coutwildrnp.shp") as collection:
        features = chain.from_iterable(repeat(list(collection), 2000))
        with fiona.open("/tmp/out.gpkg", "w", schema=collection.schema, crs=collection.crs, driver="GPKG") as dst:
            dst.writerecords(features)

And timing it:

%%timeit
test_to_file()

Before:
1min 3s ± 2.32 s per loop (mean ± std. dev. of 7 runs, 1 loop each)
After:
15.3 s ± 1.13 s per loop (mean ± std. dev. of 7 runs, 1 loop each)

[coveralls]

Coverage increased (+0.003%) to 82.629% when pulling 1a80b73 on snowman2:issue_685 into cd5da17 on Toblerity:master.

[coveralls]

Coverage increased (+0.003%) to 82.629% when pulling 1a80b73 on snowman2:issue_685 into cd5da17 on Toblerity:master.

[coveralls]

Coverage increased (+0.003%) to 82.629% when pulling 1a80b73 on snowman2:issue_685 into cd5da17 on Toblerity:master.

[coveralls]

Coverage increased (+0.003%) to 82.629% when pulling 1a80b73 on snowman2:issue_685 into cd5da17 on Toblerity:master.

[coveralls]

Coverage increased (+0.003%) to 82.629% when pulling 1a80b73 on snowman2:issue_685 into cd5da17 on Toblerity:master.

[coveralls]

Coverage increased (+0.003%) to 82.629% when pulling 1a80b73 on snowman2:issue_685 into cd5da17 on Toblerity:master.

[coveralls]

Coverage increased (+0.003%) to 82.629% when pulling 1a80b73 on snowman2:issue_685 into cd5da17 on Toblerity:master.

[coveralls]

Coverage increased (+0.003%) to 82.629% when pulling 1a80b73 on snowman2:issue_685 into cd5da17 on Toblerity:master.

[coveralls]

Coverage increased (+0.003%) to 82.629% when pulling 1a80b73 on snowman2:issue_685 into cd5da17 on Toblerity:master.

[coveralls]

Coverage increased (+0.003%) to 82.629% when pulling ee57081 on snowman2:issue_685 into cd5da17 on Toblerity:master.

[snowman2]

Looks like the GDAL trunk is using PROJ.6 now: configure: error: PROJ 6 symbols not found

[sgillies]

@snowman2 wow, great! I think I'll be able to have some review time tomorrow.

[snowman2]

Another idea I had recently was to change:

Fiona/fiona/ogrext.pyx

Line 320 in 013dec9

for key, value in feature['properties'].items():

To instead iterate over:

collection.schema['properties']

And set the property to use:

set_field_null(cogr_feature, i)

If the property does not exist in feature['properties'].

This would eliminate the need for this check:

Fiona/fiona/ogrext.pyx

Line 1167 in 013dec9

if set(record['properties'].keys()) != schema_props_keys:

But, I wanted to run the idea by you first.

[sgillies]

👍

[sgillies]

👍

[sgillies]

I made a suggestion inline

[sgillies]

@snowman2 what would you think about holding off on the schema/property checks for now? I think it's separable from elimination of the debug statements, which is a big win by itself.

I'm inclined to remove the debug statements that you've commented. I put them in when building the original feature and I don't think they are necessarily needed anymore.

[snowman2]

I'm inclined to remove the debug statements that you've commented.

I removed those in a separate commit.

what would you think about holding off on the schema/property checks for now?

I checked the difference between checking the properties and the alternative method and I was surprised that it didn't make a significant difference. So, I agree that it is an unnecessary change. It makes me wonder if it would be a good idea to do a check and remove all unnecessary log.debug/log.info statements in rasterio & fiona for performance reasons?

[sgillies]

@snorfalorpagus I tagged you for review of this, too.

[sgillies]

I edited the PR title to reflect our decision to take a one thing at a time approach to optimization.

[snorfalorpagus]

LGTM 👍