search

trim21 / transmission-rpc

https://transmission-rpc.readthedocs.io/en/stable/
MIT License
139 stars 34 forks source link

Expensive JSON serialization always run for debug logging #470

Closed rpatterson closed 3 weeks ago

rpatterson commented 3 weeks ago

Description

The transmission_rpc.client.Client._request() method logs the response JSON at the DEBUG level:

        self.logger.debug(json.dumps(data, indent=2))

Serializing the response JSON is quite expensive, and particularly so for large responses such as the torrent-get method for getting all torrents. Unfortunately, done this way, that expensive serialization is run for every request even when that log message isn't emitted.

Environment

How to reproduce

Profile code that calls the transmission_rpc.client.Client.get_torrents() method and note that the json.dumps() call constitutes much of the cumulative call time:

        2    0.028    0.014   62.821   31.411 client.py:206(_request)
        1    0.018    0.018   56.927   56.927 client.py:534(get_torrents)
        6    0.144    0.024   34.835    5.806 __init__.py:183(dumps)

This example is from a Transmission daemon with thousands of torrents run under $ python3 -m "cProfile" -s "cumulative".

Expectations

Expensive operations for DEBUG logging should not be run when DEBUG log messages aren't configured to be printed/emitted.

Actual result

The expensive JSON serialization is always run regardless of the logger's configuration.

trim21 commented 3 weeks ago

is serialize, not deserialize I think.

Is there a way to run json.dumps(data) only if debug level is enable?

If I rember this correctly, there are similar logging code for request body, too. should also change them.

But if you worried about perf, try only fetch torrent fields you need.

rpatterson commented 3 weeks ago

is serialize, not deserialize I think.

Doh! I got those backwards in my head once many years ago. I've never recovered. ;-)

Is there a way to run json.dumps(data) only if debug level is enable?

Yup, if logger.isEnabledFor(logging.DEBUG):`.

If I rember this correctly, there are similar logging code for request body, too. should also change them.

Not that I can see. I did a quick $ grep -F 'logger.debug(' *.py and this was the only instance I found.

But if you worried about perf, try only fetch torrent fields you need.

Yeah, I'm aware of that option and I've optimized that all I can but I didn't open this for my specific use case. I report this because it's about half the processing expense for all requests and that just shouldn't be for normal, IOW not DEBUG, usage.

trim21 commented 3 weeks ago

Would you like to send a PR for this?

rpatterson commented 3 weeks ago

Would you like to send a PR for this?

I don't have time to set up my test bed to use a checkout nor to figure out and add test coverage. But if you'll accept a blind, untested PR, then sure I'm happy to make the code change and submit. Would you accept that?

trim21 commented 3 weeks ago

no test coverage is needed. also no full testing is needed.

Just run any rpc command to see if it's ok. This is enough in this case, I think.

rpatterson commented 3 weeks ago

no test coverage is needed. also no full testing is needed. Just run any rpc command to see if it's ok.

That would require setting up my test-bed to use the checkout and I don't have time for that ATM. Sorry.

trim21 commented 3 weeks ago

no test coverage is needed. also no full testing is needed. Just run any rpc command to see if it's ok.

That would require setting up my test-bed to use the checkout and I don't have time for that ATM. Sorry.

ci will do it