{Core} Config knack only once

[jiasli]

Description

#16301 introduced function _configure_knack.

During tests, AzCli can be created multiple times in the same process, causing _configure_knack to be executed multiple times, resulting in duplicated 'azure' entries in cli_logger_names:

['cli', 'azure', 'azure', 'azure', 'azure', ...]

This causes huge delay on CLI Automation Full Test / Automation Test Python38.

https://dev.azure.com/azure-sdk/public/_pipeline/analytics/duration?definitionId=1623&contextType=build

https://dev.azure.com/azure-sdk/public/_build/results?buildId=697879&view=results

• Automation Test Python36: 25m 30s
• Automation Test Python38: 56m 1s

Tested with Python 3.7 and it also suffers from the slowness.

Changes

This PR utilizes Python's module cache to make sure cli_logger_names is only changed once to

['cli', 'azure']

[yonzhan]

Core

[jiasli]

It turns out the culprit is Logger.setLevel which is much slower on Python 3.8 and 3.7 than that on Python 3.6.

Tested with:

import logging
import timeit

# Create many loggers
for i in range(300):
    logging.getLogger("azure.{}".format(i))

ITERATION_COUNT = 5000

start = timeit.default_timer()

# Call getLogger many times
for i in range(ITERATION_COUNT):
    logging.getLogger('azure')
print("getLogger takes", timeit.default_timer() - start)

# Call setLevel many times
cli_logger = logging.getLogger('azure')
start = timeit.default_timer()
for i in range(ITERATION_COUNT):
    cli_logger.setLevel(logging.DEBUG)
print("setLevel takes", timeit.default_timer() - start)

> ~\AppData\Local\Programs\Python\Python38\python.exe test.py
getLogger takes 0.004355399999999995
setLevel takes 0.18627549999999998  # Very slow
> ~\AppData\Local\Programs\Python\Python36\python.exe test.py
getLogger takes 0.0050362
setLevel takes 0.0028270000000000005

python/cpython#2752 added _clear_cache to Logger.setLevel:

def setLevel(self, level):
    ...
    self.manager._clear_cache()

_clear_cache clears the _cache of all loggers. When the logger count increases, this function becomes very heavy.

def _clear_cache(self):
    ...
    for logger in self.loggerDict.values():
        if isinstance(logger, Logger):
            logger._cache.clear()

Since Logger.setLevel is not frequently called, the benefit of python/cpython#2752 overweigh its harm.

To analyze the performance impact, we can focus on for loops. Consider this for pattern:

def location():
    for item in target:
        operation()

for location	for target	for operation	count	mitigation	reduced count
Logger.setLevel	loggers [1]	dict.clear	300	N/A [3]	300
CLILogging.configure	cli_logger_names [2]	Logger.setLevel	5000	This PR	2 (['cli', 'azure'])
nosetests	commands	CLILogging.configure	10000	knack#228	1

• [1] each from one .py file's get_logger(__name__)
• [2] which contains multiple 'azure's, each added by AzCli.__init__, called by one ScenarioTest
• [3] Python 3.7 added this logic (bpo-30962: Add caching to Logger.isEnabledFor() python/cpython#2752)
• Each command executes 300*5000=1500000 dict.clears, causing 0.2s delay.
• The full test executes totally 1500000*10000=15000000000 dict.clears, causing 10000*0.2=2000s delay.

[yonzhan]

A very good example for getting to the bottom and driving to the end!! I love it.

[evelyn-ys]

kneels down