Project

General

Profile

Actions
Copy link

Bug #13987

closed

Massive performance penalty in policy generation due to invalid usage of StringTemplate

Added by Nicolas CHARLES over 5 years ago. Updated over 5 years ago.

Status:
Released
Priority:
N/A
Assignee:
François ARMAND
Category:
Performance and scalability
Target version:
4.3.8
Pull Request:
https://github.com/Normation/rudder/p...
Severity:
UX impact:
User visibility:
Effort required:
Priority:
0
Name check:
Fix check:
Regression:

Description

We are using String Template in a non efficient way: for each node, for each template, we are re-tokenizing the template
We should instead use a copy of the tokenized version (as sescribed in https://theantlrguy.atlassian.net/wiki/spaces/ST/pages/1409053/ST+condensed+--+Templates+and+groups)

Perf increase is quite impressive:
Without cache of tokenization

[2018-12-17 17:17:42] INFO  policy.generation - Build target configuration    :       8914 ms
[2018-12-17 17:17:42] INFO  policy.generation - Write node configurations     :      84801 ms
[2018-12-17 17:17:42] INFO  policy.generation - Save expected reports         :        785 ms
[2018-12-17 17:17:42] INFO  policy.generation - Run post generation hooks     :         67 ms
[2018-12-17 17:17:42] INFO  policy.generation - Number of nodes updated       :       1597  
[2018-12-17 17:17:42] INFO  policy.generation - StringTemplate related stats: total time of new StringTemplate     :      54574 ms  
[2018-12-17 17:17:42] INFO  policy.generation - StringTemplate related stats: total time of replacement of var     :        467 ms  
[2018-12-17 17:17:42] INFO  policy.generation - StringTemplate related stats: nbTemaplte    :      60110    
[2018-12-17 17:17:42] INFO  policy.generation - Policy generation completed in:     109967 ms

With cache of tokenization

[2018-12-17 17:12:27] INFO  policy.generation - Build target configuration    :       8114 ms
[2018-12-17 17:12:27] INFO  policy.generation - Write node configurations     :      30503 ms
[2018-12-17 17:12:27] INFO  policy.generation - Save expected reports         :        781 ms
[2018-12-17 17:12:27] INFO  policy.generation - Run post generation hooks     :         91 ms
[2018-12-17 17:12:27] INFO  policy.generation - Number of nodes updated       :       1597  
[2018-12-17 17:12:27] INFO  policy.generation - StringTemplate related stats: total time of new StringTemplate     :        293 ms  
[2018-12-17 17:12:27] INFO  policy.generation - StringTemplate related stats: total time of replacement of var     :        430 ms  
[2018-12-17 17:12:27] INFO  policy.generation - StringTemplate related stats: nbTemaplte    :      60110    
[2018-12-17 17:12:27] INFO  policy.generation - Policy generation completed in:      57362 ms

we can contemplate a *2 perf increase

Files

Download all files
with.png (67.9 KB) with.png with the patch Nicolas CHARLES, 2018-12-17 23:15
without.png (82.7 KB) without.png without the patch Nicolas CHARLES, 2018-12-17 23:15

Related issues 1 (0 open — 1 closed)

Related to Rudder - Bug #14322: Directive parameter values are mixed between directivesReleasedFrançois ARMANDActions
Actions
Copy link
 #1

Updated by Nicolas CHARLES over 5 years ago

  • Status changed from New to In progress
  • Assignee set to Nicolas CHARLES
Actions
Copy link
 #2

Updated by Nicolas CHARLES over 5 years ago

  • Status changed from In progress to Pending technical review
  • Assignee changed from Nicolas CHARLES to François ARMAND
  • Pull Request set to https://github.com/Normation/rudder/pull/2098
Actions
Copy link
 #3

Updated by Rudder Quality Assistant over 5 years ago

  • Status changed from Pending technical review to Discussion
  • Assignee changed from François ARMAND to Nicolas CHARLES
Actions
Copy link
 #4

Updated by Nicolas CHARLES over 5 years ago

  • Status changed from Discussion to Pending technical review
  • Assignee changed from Nicolas CHARLES to François ARMAND
Actions
Copy link Download all files
 #5

Updated by Nicolas CHARLES over 5 years ago

More details: after 3 full policy generation, with 1600 nodes 

[2018-12-17 22:58:33] INFO  policy.generation - Timing summary:
[2018-12-17 22:58:33] INFO  policy.generation - Run pre-gen scripts hooks     :          0 ms
[2018-12-17 22:58:33] INFO  policy.generation - Run pre-gen modules hooks     :          0 ms
[2018-12-17 22:58:33] INFO  policy.generation - Fetch all information         :        162 ms
[2018-12-17 22:58:33] INFO  policy.generation - Historize names               :        577 ms
[2018-12-17 22:58:33] INFO  policy.generation - Build current rule values     :         43 ms
[2018-12-17 22:58:33] INFO  policy.generation - Build target configuration    :       7184 ms
[2018-12-17 22:58:33] INFO  policy.generation - Write node configurations     :      17176 ms
[2018-12-17 22:58:33] INFO  policy.generation - Save expected reports         :        704 ms
[2018-12-17 22:58:33] INFO  policy.generation - Run post generation hooks     :          5 ms
[2018-12-17 22:58:33] INFO  policy.generation - Number of nodes updated       :       1597   
[2018-12-17 22:58:33] INFO  policy.generation - Policy generation completed in:      41858 ms

before

[2018-12-17 23:09:30] INFO  policy.generation - Run pre-gen scripts hooks     :          0 ms
[2018-12-17 23:09:30] INFO  policy.generation - Run pre-gen modules hooks     :          0 ms
[2018-12-17 23:09:30] INFO  policy.generation - Fetch all information         :        151 ms
[2018-12-17 23:09:30] INFO  policy.generation - Historize names               :        472 ms
[2018-12-17 23:09:30] INFO  policy.generation - Build current rule values     :         52 ms
[2018-12-17 23:09:30] INFO  policy.generation - Build target configuration    :       8278 ms
[2018-12-17 23:09:30] INFO  policy.generation - Write node configurations     :      33907 ms
[2018-12-17 23:09:30] INFO  policy.generation - Save expected reports         :        747 ms
[2018-12-17 23:09:30] INFO  policy.generation - Run post generation hooks     :          5 ms
[2018-12-17 23:09:30] INFO  policy.generation - Number of nodes updated       :       1597   
[2018-12-17 23:09:30] INFO  policy.generation - Policy generation completed in:      57950 ms

So the step "Write node configurations" is twice as fast with this, and the overall policy generation is 30% faster. This improvement scales with the number of directives used - so the larger the configuration, the better the improvement is.

Attached, the visualvm of the policy generation, with this modification and without - the difference in total memory is most likely due to difference in compliance

Actions
Copy link
 #6

Updated by Nicolas CHARLES over 5 years ago

  • Status changed from Discussion to Pending technical review
  • Assignee changed from Nicolas CHARLES to François ARMAND
Actions
Copy link
 #7

Updated by Rudder Quality Assistant over 5 years ago

  • Status changed from Pending technical review to Discussion
  • Assignee changed from François ARMAND to Nicolas CHARLES
Actions
Copy link
 #8

Updated by Nicolas CHARLES over 5 years ago

  • Status changed from Discussion to Pending technical review
  • Assignee changed from Nicolas CHARLES to François ARMAND
Actions
Copy link
 #9

Updated by Nicolas CHARLES over 5 years ago

  • Status changed from Pending technical review to Pending release
Actions
Copy link
 #10

Updated by Vincent MEMBRÉ over 5 years ago

  • Status changed from Pending release to Released
This bug has been fixed in Rudder 4.3.8 and 5.0.4 which were released today. 
Changelog
 Changelog
Actions
Copy link
 #11

Updated by Nicolas CHARLES about 5 years ago

  • Related to Bug #14322: Directive parameter values are mixed between directives added
Actions
Copy link

Also available in: Atom PDF