Project

General

Profile

Bug #12730

Moving policies to their final position (last step of policies writing) could be improved

Added by Nicolas CHARLES 6 months ago. Updated 5 months ago.

Status:
Released
Priority:
N/A
Category:
Performance and scalability
Target version:
Severity:
User visibility:
Effort required:
Priority:
0

Description

On a small test with 428 nodes, stats of policies generation are:

[2018-05-31 23:04:20] DEBUG policy.generation - Paths computed and templates read in 48 ms
[2018-05-31 23:04:21] DEBUG policy.generation - Promises prepared in 502 ms
[2018-05-31 23:04:28] DEBUG policy.generation - Promises written in 7424 ms
[2018-05-31 23:04:28] DEBUG policy.generation - Properties written in 10 ms
[2018-05-31 23:04:28] DEBUG policy.generation - Parameters written in 12 ms
[2018-05-31 23:04:28] DEBUG policy.generation - Licenses copied in 0 ms
[2018-05-31 23:04:30] DEBUG policy.generation - Policies moved to their final position in 1948 ms
[2018-05-31 23:04:30] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration written on filesystem in 10287 ms
[2018-05-31 23:04:31] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration cached in LDAP in 383 ms
[2018-05-31 23:04:31] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration written in 10921 ms, start to update expected reports.
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Reports updated in 2072 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Post-policy-generation hooks ran in 2 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Timing summary:
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Run pre-gen scripts hooks :          0 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Run pre-gen modules hooks :          0 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Fetch all information     :        319 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Historize names           :        400 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Build current rule values :          2 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Build target configuration:       2302 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Update rule vals          :        130 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Increment rule serials    :        946 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Write node configurations :      10921 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Save expected reports     :       2072 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Run post generation hooks :          2 ms
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Number of nodes updated   :        428   
[2018-05-31 23:04:33] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Policy generation completed in 17725 ms

Moving policies takes 1 948 out of 10 921ms of write node configuration (20%)
this is surprisingly slow: this in only renaming of 428 folder

Associated revisions

Revision 7a1933c9 (diff)
Added by Nicolas CHARLES 6 months ago

Fixes #12730: Moving policies to their final position (last step of policies writing) could be improved

History

#1 Updated by Nicolas CHARLES 6 months ago

Culprit is FileUtils.forceDelete(dest)
When using FileUtils.moveDirectory, we need to have the destination empty, so clean the folder dest, which is pretty slow

#2 Updated by Nicolas CHARLES 6 months ago

unfortunately, renameTo is pretty fast, but need the target destination to be empty as well

#3 Updated by Nicolas CHARLES 6 months ago

backup $ time `rm -rf *`

real    0m0.454s
user    0m0.048s
sys    0m0.344s

removing all backup takes ,3s; so fastest all deletion could be 0,6s, plus the move of each folder. We can gain a bit there, but I don't know how

#4 Updated by Nicolas CHARLES 6 months ago

One idea would be to run the cleaning of backups asynchronously: either earlier (like, once we know some node will have their promises deleted), or if we generate node by node, this will by itself splay over the generation

#5 Updated by Nicolas CHARLES 6 months ago

  • Subject changed from Moving policies to their final position (last step of policies writing) is quite inefficient to Moving policies to their final position (last step of policies writing) could be improved

Ok, measures are weird - I get from 670ms to 3500ms for the move policies to final position. Either something is messing with my results, or system cache is playing some tricks on me (or my ssd is failing...)

Anyway, i'll propose a minimal change (not checking twice that a directory is a directory)

#6 Updated by Nicolas CHARLES 6 months ago

  • Status changed from New to In progress
  • Assignee set to Nicolas CHARLES

#7 Updated by Nicolas CHARLES 6 months 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/1955

#8 Updated by Nicolas CHARLES 6 months ago

  • Status changed from Pending technical review to Pending release

#9 Updated by Vincent MEMBRÉ 5 months ago

  • Status changed from Pending release to Released

This bug has been fixed in Rudder 4.1.13, 4.2.7 and 4.3.3 which were released today.

Also available in: Atom PDF