Rudder

Policy generation is really slow in 6.1, and it seem that policy writing isn't parrarel

[2020-05-04 04:55:11] INFO  policy.generation - [metrics] Xmx:20.5 GB nodes:4551 (cached:0) rules:161 (enabled:160) techniques:50 (enabled:50) directives:330 (enabled:330) groups:460 (dynamic:460) parameters:3
[2020-05-04 04:55:18] DEBUG policy.generation.timing - Historization of names done in 6701 ms, start to build rule values.
[2020-05-04 04:55:20] DEBUG policy.generation.timing - RuleVals built in 1917 ms, start to expand their values.
[2020-05-04 04:56:07] DEBUG policy.generation.timing - Merge group properties took 7942 ms for 4551 nodes
[2020-05-04 04:56:07] DEBUG policy.generation.timing - Node contexts built in 47215 ms, start to build new node configurations.
[2020-05-04 04:58:34] TRACE policy.generation.timing.buildNodeConfig -  - create filtered policy drafts: 76 ms
[2020-05-04 04:58:34] TRACE policy.generation.timing.buildNodeConfig -  - compile global and nodes paramaters: 40 ms
[2020-05-04 04:58:34] TRACE policy.generation.timing.buildNodeConfig -  - created bounded policy drafts: 700083 ms (number of drafts: 602382)
[2020-05-04 04:58:34] TRACE policy.generation.timing.buildNodeConfig -  - - expand parameter: 32560 ms
[2020-05-04 04:58:34] TRACE policy.generation.timing.buildNodeConfig -  - - evaluate JS: 631817  (number of evaluation: 6774452)
[2020-05-04 04:58:34] TRACE policy.generation.timing.buildNodeConfig -  - merge policy draft to get policies: 31722 ms
[2020-05-04 04:58:34] DEBUG policy.generation.timing.buildNodeConfig - Total run config: 146646 ms
[2020-05-04 04:58:34] DEBUG policy.generation.timing - Node's target configuration built in 146828 ms, start to update rule values.
[2020-05-04 04:58:42] INFO  policy.generation - Configuration of 4551 nodes were updated, their policies are going to be written
[2020-05-04 04:58:53] DEBUG policy.generation.timing - 60 promises templates read in 104 ms
[2020-05-04 04:58:53] DEBUG policy.generation.timing - 63 promises resources read in 66 ms
[2020-05-04 04:58:53] DEBUG policy.generation.timing - Paths computed and templates read in 346 ms
[2020-05-04 04:59:10] DEBUG policy.generation.timing - Policy templates prepared in 16471 ms
[2020-05-04 04:59:10] TRACE policy.generation.timing -  -> bundle sequence built in 15527 ms | agent system variables built in 680 ms | policy template prepared in 65036 ms
[2020-05-04 05:10:02] DEBUG policy.generation - Flag file '/opt/rudder/etc/policy-update-running' created
[2020-05-04 05:10:02] DEBUG policy.generation - Flag file '/opt/rudder/etc/policy-update-running' created
[2020-05-04 05:10:02] INFO  policy.generation - One automatic policy update process is already pending, replacing by a manual request
[2020-05-04 05:10:09] INFO  scheduled.job - Update in node inventories main information detected: triggering a policy generation
[2020-05-04 05:10:09] DEBUG policy.generation - Flag file '/opt/rudder/etc/policy-update-running' created
[2020-05-04 05:10:09] INFO  policy.generation - One policy update process is already pending, ignoring new policy update request
[2020-05-04 05:10:54] INFO  scheduled.job - Update in node inventories main information detected: triggering a policy generation
[2020-05-04 05:10:54] DEBUG policy.generation - Flag file '/opt/rudder/etc/policy-update-running' created
[2020-05-04 05:10:54] INFO  policy.generation - One policy update process is already pending, ignoring new policy update request
[2020-05-04 05:11:39] INFO  scheduled.job - Update in node inventories main information detected: triggering a policy generation
[2020-05-04 05:11:39] DEBUG policy.generation - Flag file '/opt/rudder/etc/policy-update-running' created
[2020-05-04 05:11:39] INFO  policy.generation - One policy update process is already pending, ignoring new policy update request
[2020-05-04 05:12:24] INFO  scheduled.job - Update in node inventories main information detected: triggering a policy generation
[2020-05-04 05:12:24] DEBUG policy.generation - Flag file '/opt/rudder/etc/policy-update-running' created
[2020-05-04 05:12:24] INFO  policy.generation - One policy update process is already pending, ignoring new policy update request
[2020-05-04 05:13:09] INFO  scheduled.job - Update in node inventories main information detected: triggering a policy generation
[2020-05-04 05:13:09] DEBUG policy.generation - Flag file '/opt/rudder/etc/policy-update-running' created
[2020-05-04 05:13:09] INFO  policy.generation - One policy update process is already pending, ignoring new policy update request
[2020-05-04 05:25:52] DEBUG policy.generation.timing - Policies written in 1602258 ms
[2020-05-04 05:25:52] TRACE policy.generation.timing -  -> fill template: 281569 ms [fill template: 73822 ms | to string template: 202262 ms | fill template wait: 0 ms | get template exec: 142 ms | get template wait: 0 ms]
[2020-05-04 05:25:52] TRACE policy.generation.timing -  -> write template: 1800296 ms | copy resources: 671030 ms | agent specific: 384 ms | write CSV: 131910 ms| write JSON: 178058 ms
[2020-05-04 05:25:52] DEBUG policy.generation.timing - Getting info for timing trace in 2 ms
[2020-05-04 05:26:12] DEBUG policy.generation.timing - Properties written in 19691 ms
[2020-05-04 05:26:21] DEBUG policy.generation.timing - Parameters written in 9515 ms
[2020-05-04 05:29:33] DEBUG policy.generation.timing.hooks - Hooks for policy-generation-node-ready executed in 192115 ms
[2020-05-04 05:29:33] DEBUG policy.generation - Using atomic move for node policies
[2020-05-04 05:30:23] DEBUG policy.generation.timing - Policies moved to their final position in 49604 ms
[2020-05-04 05:30:23] DEBUG policy.generation.timing.hooks - Hooks for policy-generation-node-finished executed in 499 ms
[2020-05-04 05:30:23] DEBUG policy.generation.timing - Node configuration written on filesystem in 1890679 ms
[2020-05-04 05:30:41] DEBUG policy.generation.timing - Node configuration cached in LDAP in 17297 ms
[2020-05-04 05:30:41] DEBUG policy.generation.timing - Node configuration written in 1907981 ms, start to update expected reports.
[2020-05-04 05:30:43] DEBUG policy.generation.timing - Reports computed in 2219 ms
[2020-05-04 05:31:22] DEBUG policy.generation.timing - Node expected reports saved in base in 39415 ms.
[2020-05-04 05:31:22] WARN  hooks - More than 3000 nodes where updated and 'policy-generation-finished' user hooks are present. The parameter 'RUDDER_NODE_IDS' will be unset due to https://issues.rudder.io/issues/15011. Update your hooks accordinbly to the ticket workaround, then set rudder configuration parameter 'rudder.hooks.policy-generation-finished.nodeids.compability' to false and restart Rudder.
[2020-05-04 05:31:23] DEBUG policy.generation.timing - Post-policy-generation hooks ran in 394 ms
[2020-05-04 05:31:23] INFO  policy.generation.timing - Timing summary:
[2020-05-04 05:31:23] INFO  policy.generation.timing - Run pre-gen scripts hooks     :          2 ms
[2020-05-04 05:31:23] INFO  policy.generation.timing - Run pre-gen modules hooks     :          0 ms
[2020-05-04 05:31:23] INFO  policy.generation.timing - Fetch all information         :        600 ms
[2020-05-04 05:31:23] INFO  policy.generation.timing - Historize names               :       6701 ms
[2020-05-04 05:31:23] INFO  policy.generation.timing - Build current rule values     :       1917 ms
[2020-05-04 05:31:23] INFO  policy.generation.timing - Build target configuration    :     146828 ms
[2020-05-04 05:31:23] INFO  policy.generation.timing - Write node configurations     :    1907981 ms
[2020-05-04 05:31:23] INFO  policy.generation.timing - Save expected reports         :       2219 ms
[2020-05-04 05:31:23] INFO  policy.generation.timing - Run post generation hooks     :        394 ms
[2020-05-04 05:31:23] INFO  policy.generation.timing - Number of nodes updated       :       4551   
[2020-05-04 05:31:23] INFO  policy.generation.timing - Policy generation succeeded in: 36 min 12 s

there is only one thread apparently writing file (see attached jstack)
it may or may not be related to change in chmod
DEBUG policy.generation - Policy generation parallelism set to: 5 (change with REST API settings parameter 'rudder_generation_max_parallelism')