Reducing the number of telemetry logs to reduce the impact of telemetry throttling on performance of Assessment and Install Updates jobs

[GAURAVRAMRAKHYANI]

Reducing the number of telemetry logs to reduce the impact of telemetry throttling on performance of assessment and Install Updates jobs. Reducing the logs by two ways:

(a) Removing the logs which are not required for debugging.

(b) Currently there is separate log for each line for extract dependencies from output. We don't need log for each line for debugging. Removing log for the lines which are not required for debugging. Also updating to have single log instead of multiple logs for each lines which are required for debugging. There is one problem with having single log i.e. it might exceed the limit of characters in a single log and hence there will be truncation of log. But as per below analysis, this should happen when number of dependent packages is more than 20 which is very rare case.

The limit of characters per log is TELEMETRY_MSG_SIZE_LIMIT_IN_CHARS - (TELEMETRY_BUFFER_FOR_DROPPED_COUNT_MSG_IN_CHARS + TELEMETRY_EVENT_COUNTER_MSG_SIZE_LIMIT_IN_CHARS) = 3072 - (25 + 15) = 3072 - 40 = 3032 characters
There are two kinds of logs in the output of command to get dependencies:
(i) LogType1: Logs with "Inapplicable line: " - This log take around 100 characters, it depends on package name and version
(ii) LogType2: Logs with "Dependency decteded: " - This log take around 50 characters, it depends on package name, the package version is not there in this line

For each package in the output, there is one LogType1 and LogType2.

So, total package details which can be there in single log = (Character limit per log)/(Number of characters per package) = 3032/150 = 20 packages
So, if there are more than 20 packages as dependency then only there will be some truncation in the log. The 20 packages dependency is very rare scenario.

Testing completed:
Tested with two VMs with RHEL 7.8 Gen2 and 208 updates to install. In one VM the install updates job is run without changes and in the other one it is run with the changes. The time taken for job to complete in VM without changes is 139 minutes and the time taken for job to complete in VM with the changes is 87 minutes. So, there is around (139-87)/139 = 37.41% improvement in performance.
I also looked into the logs and the logs are good for debugging.

In first iteration this change is done for only YUM package manager. When it is reviewed then the changes will be done for Apt and Zypper.

[codecov]

Codecov Report

Merging #211 (b9bd5b2) into master (4fa74fa) will increase coverage by 0.05%.
Report is 1 commits behind head on master.
The diff coverage is 100.00%.

@@            Coverage Diff             @@
##           master     #211      +/-   ##
==========================================
+ Coverage   90.14%   90.19%   +0.05%     
==========================================
  Files          90       90              
  Lines       14475    14486      +11     
==========================================
+ Hits        13048    13066      +18     
+ Misses       1427     1420       -7     

Flag	Coverage Δ
python27	90.19% <100.00%> (+0.05%)	⬆️
python39	90.19% <100.00%> (+0.05%)	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Files Changed	Coverage Δ
src/core/src/package_managers/YumPackageManager.py	84.69% <100.00%> (+1.35%)	⬆️

... and 1 file with indirect coverage changes

[kjohn-msft]

Conceptually exactly as I'd want it, but the outcome needs to be achieved in code a little differently:
Composite logger log functions can be extended to have built in buffers for each log type.

The buffer can be an optional parameter that defaults to false on the logging function. buffer = true, false, flush*

If the buffer is true, keep appending to built-in variable.

The buffer may be flushed to the log in the very last message meant to be part of the concatenation.

If it's false, write whatever is in memory, clear it out, and also separately write the new message that came in. <-- This is not expected to have to flush anything if the flush call was made correctly. The flush is necessary to avoid losing in-memory data in case of a subsequent unhandled exception.

The buffer line separator can be what's already used in package manager output - "\n|\t"

The benefit of doing this is that existing code can be changed very minimally, and won't be peppered with additional temporary variables everywhere.

General note: This wasn't part of AzGPS Gallium commitments, but low-cost, precise PRs may be taken if it affects no other committed deliverables. Post the base implementation on composite_logger, please PR one major file at a time to reduce merge conflicts for other code in the pipeline, and to also make it easier for reviewers. Also focus on high-time complexity code - especially in tight loops or frequently executed code.

[kjohn-msft]

I expect this to be a sequence of PRs, with the first being the base CompositeLogger implementation (as in note left).

Since this will be a base CompositeLogger implementation, please rename title to reflect for merge history.

[GAURAVRAMRAKHYANI]

Closing this PR. This will be handled through sequence of PRs with the first being the base CompositeLogger implementation. The comments by Koshy in this PR describe the design.
New PR for compositeLogger changes: #213