Log messages lazily

[jjlin]

The existing logger is called LazyLogger, but it isn't actually being used as intended, as pretty much all log messages are currently being formatted eagerly.

This is mostly a pretty mechanical conversion that aims to maintain equivalent behavior, but I also fixed a few typos in the log messages.

[mcarlton00]

This is noticeably slower than current master on my rigs. If it was faster I could maybe be convinced, but performing worse and sending us back to the ugly python 2.5 days of formatting, this is a hard sell.

Movies library - current master

178160 function calls (178043 primitive calls) in 5.138 seconds

Same movies library - this PR

178351 function calls (178137 primitive calls) in 6.643 seconds

imo, doing this for strings, which is the vast majority of our log messages, really isn't going to save anything, just makes the code harder to read. Doing it for json blogs or dicts is where there's might be a meaningful benefit, like what was done here: https://github.com/jellyfin/jellyfin-kodi/pull/193/changes

[jjlin]

Are you logging at debug level though? If so, I could see how (and even expect that) it might be a little slower. But for the people who aren't (i.e., most people), I don't see why it would be slower.

[mcarlton00]

Logging is at info level. I haven't dug into the how or why, but it doesn't seem like this is working as intended. I think that LazyLogger class is also more for import management than how you interpreted it, but I could be wrong. it's been a long time.

[jjlin]

Yeah, LazyLogger is more of an import helper thing:

jellycon/resources/lib/lazylogger.py

Line 18 in b1cabe9

from .loghandler import getLogger

But it just ends up importing from the standard library logging package, which does implement the type of lazy logging that is typical across a bunch of languages:

jellycon/resources/lib/loghandler.py

Line 132 in b1cabe9

__LOGGER = logging.getLogger('JELLYFIN')

This is a standard best practice (see e.g. https://medium.com/flowe-ita/logging-should-be-lazy-bc6ac9816906, which isn't an authoritative source or anything, but looks like a reasonable summary), so I suspect there's probably something else going on with your timings. Is it a single run or did you try it several times?

To be fair, this is more of a general cleanup item and I doubt it would improve (or hurt) performance very noticeably, as other things like network or server response time variability are much more likely to dominate. I've been running with these changes for a couple weeks and I haven't noticed anything remarkable.

[mcarlton00]

I ran it three times on each version to make sure it wasn't a fluke.

Theoretically it should result in better performance, if I'm understanding things correctly. Since according to the documentation it's delaying rendering out the logged message values until they're actually needed. Not that I anticipate any of these string variables will have a meaningful influence one way or the other, but the profiler should at least show a marginal reduction in processing times. Giving worse performance is about as backwards a result as can be expected here.

[jjlin]

Could you provide more details on the procedure you used to get your numbers? I'd like to try to reproduce your results and understand how that could be happening. Thanks.

[mcarlton00]

I'm using the profiler built into the addon. I just made a slight tweak to it locally to ignore this counter so it always runs instead of only a limited number of page loads.

jellycon/resources/lib/functions.py

Lines 62 to 64 in 944da7a

	if profile_count > 0:
	profile_count = profile_count - 1
	settings.setSetting('profile_count', str(profile_count))