Project

General

Profile

Actions

Bug #17315

closed

policy generation - writing file - doesn't seem parralelised

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

Status:
Rejected
Priority:
N/A
Assignee:
-
Category:
Performance and scalability
Target version:
Severity:
UX impact:
User visibility:
Effort required:
Priority:
0
Name check:
To do
Fix check:
To do
Regression:

Description

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')


Files

stack (131 KB) stack Nicolas CHARLES, 2020-05-04 07:43

Related issues 1 (0 open1 closed)

Related to Rudder - Bug #17214: chmod at the end of policy generation is painfully slowReleasedFrançois ARMANDActions
Actions #1

Updated by Nicolas CHARLES over 4 years ago

  • Related to Bug #17214: chmod at the end of policy generation is painfully slow added
Actions #2

Updated by Nicolas CHARLES over 4 years ago

it used to be ok with a 6.1 build on the 19/04

[2020-04-24 23:15:59] DEBUG policy.generation.timing - Policy templates prepared in 14661 ms
[2020-04-24 23:15:59] TRACE policy.generation.timing -  -> bundle sequence built in 11725 ms | agent system variables built in 247 ms | policy template prepared in 59769 ms
[2020-04-24 23:23:14] DEBUG policy.generation.timing - Policies written in 434815 ms
[2020-04-24 23:23:14] TRACE policy.generation.timing -  -> fill template: 239035 ms [fill template: 59162 ms | to string template: 174897 ms | fill template wait: 0 ms | get template exec: 64 ms | get template wait: 0 ms]
[2020-04-24 23:23:14] TRACE policy.generation.timing -  -> write template: 634726 ms | copy resources: 38714 ms | agent specific: 191 ms | write CSV: 5948 ms| write JSON: 13839 ms
[2020-04-24 23:23:14] DEBUG policy.generation.timing - Getting info for timing trace in 3 ms
[2020-04-24 23:23:16] DEBUG policy.generation.timing - Properties written in 1860 ms
[2020-04-24 23:23:16] DEBUG policy.generation.timing - Parameters written in 615 ms
[2020-04-24 23:23:42] DEBUG policy.generation.timing.hooks - Hooks for policy-generation-node-ready executed in 25831 ms
[2020-04-24 23:23:42] DEBUG policy.generation - Using atomic move for node policies
[2020-04-24 23:24:30] DEBUG policy.generation.timing - Policies moved to their final position in 47440 ms
[2020-04-24 23:24:30] DEBUG policy.generation.timing.hooks - Hooks for policy-generation-node-finished executed in 505 ms
[2020-04-24 23:24:30] DEBUG policy.generation.timing - Node configuration written on filesystem in 527791 ms
[2020-04-24 23:24:52] DEBUG policy.generation.timing - Node configuration cached in LDAP in 22168 ms
[2020-04-24 23:24:52] DEBUG policy.generation.timing - Node configuration written in 549963 ms, start to update expected reports.
[2020-04-24 23:24:55] DEBUG policy.generation.timing - Reports computed in 2361 ms
[2020-04-24 23:25:33] DEBUG policy.generation.timing - Node expected reports saved in base in 38421 ms.
[2020-04-24 23:25:33] 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-04-24 23:25:34] DEBUG policy.generation.timing - Post-policy-generation hooks ran in 506 ms
[2020-04-24 23:25:34] INFO  policy.generation.timing - Timing summary:
[2020-04-24 23:25:34] INFO  policy.generation.timing - Run pre-gen scripts hooks     :          3 ms
[2020-04-24 23:25:34] INFO  policy.generation.timing - Run pre-gen modules hooks     :          1 ms
[2020-04-24 23:25:34] INFO  policy.generation.timing - Fetch all information         :       3270 ms
[2020-04-24 23:25:34] INFO  policy.generation.timing - Historize names               :     110237 ms
[2020-04-24 23:25:34] INFO  policy.generation.timing - Build current rule values     :       2225 ms
[2020-04-24 23:25:34] INFO  policy.generation.timing - Build target configuration    :     165792 ms
[2020-04-24 23:25:34] INFO  policy.generation.timing - Write node configurations     :     549963 ms
[2020-04-24 23:25:34] INFO  policy.generation.timing - Save expected reports         :       2361 ms
[2020-04-24 23:25:34] INFO  policy.generation.timing - Run post generation hooks     :        506 ms
[2020-04-24 23:25:34] INFO  policy.generation.timing - Number of nodes updated       :       4549  
[2020-04-24 23:25:34] INFO  policy.generation.timing - Policy generation succeeded in: 15 min 31 s
Actions #3

Updated by Vincent MEMBRÉ over 4 years ago

  • Target version changed from 6.1.0~beta2 to 6.1.0~beta3
Actions #4

Updated by Nicolas CHARLES over 4 years ago

  • Status changed from New to Rejected

rejecting, as it seems it was bad luck

[2020-05-04 10:10:02] DEBUG policy.generation.timing - Computing dynamic groups finished in 83 ms
[2020-05-04 10:10:02] DEBUG policy.generation.timing - Pre-policy-generation scripts hooks ran in 19 ms
[2020-05-04 10:10:02] DEBUG policy.generation.timing - Pre-policy-generation modules hooks in 0 ms, start getting all generation related data.
[2020-05-04 10:10:02] TRACE policy.generation.timing - Fetched rules in 61 ms
[2020-05-04 10:10:06] TRACE policy.generation.timing - Fetched node infos in 4066 ms
[2020-05-04 10:10:06] TRACE policy.generation.timing - Fetched directives in 116 ms
[2020-05-04 10:10:07] TRACE policy.generation.timing - Fetched groups in 515 ms
[2020-05-04 10:10:07] TRACE policy.generation.timing - Fetched global parameters in 3 ms
[2020-05-04 10:10:07] TRACE policy.generation.timing - Fetched run infos in 12 ms
[2020-05-04 10:10:07] DEBUG policy.generation.timing - All relevant information fetched in 4794 ms, start names historization.
[2020-05-04 10:10:07] 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 10:10:17] DEBUG policy.generation.timing - Historization of names done in 10173 ms, start to build rule values.
[2020-05-04 10:10:20] DEBUG policy.generation.timing - RuleVals built in 3021 ms, start to expand their values.
[2020-05-04 10:11:16] DEBUG policy.generation.timing - Merge group properties took 6645 ms for 4551 nodes
[2020-05-04 10:11:16] DEBUG policy.generation.timing - Node contexts built in 56695 ms, start to build new node configurations.
[2020-05-04 10:13:34] TRACE policy.generation.timing.buildNodeConfig -  - create filtered policy drafts: 39 ms
[2020-05-04 10:13:34] TRACE policy.generation.timing.buildNodeConfig -  - compile global and nodes paramaters: 20 ms
[2020-05-04 10:13:34] TRACE policy.generation.timing.buildNodeConfig -  - created bounded policy drafts: 654642 ms (number of drafts: 602382)
[2020-05-04 10:13:34] TRACE policy.generation.timing.buildNodeConfig -  - - expand parameter: 36449 ms
[2020-05-04 10:13:34] TRACE policy.generation.timing.buildNodeConfig -  - - evaluate JS: 580545  (number of evaluation: 6774452)
[2020-05-04 10:13:34] TRACE policy.generation.timing.buildNodeConfig -  - merge policy draft to get policies: 32058 ms
[2020-05-04 10:13:34] DEBUG policy.generation.timing.buildNodeConfig - Total run config: 137524 ms
[2020-05-04 10:13:34] DEBUG policy.generation.timing - Node's target configuration built in 137671 ms, start to update rule values.
[2020-05-04 10:13:43] INFO  policy.generation - Configuration of 4551 nodes were updated, their policies are going to be written
[2020-05-04 10:13:53] DEBUG policy.generation.timing - 60 promises templates read in 82 ms
[2020-05-04 10:13:53] DEBUG policy.generation.timing - 63 promises resources read in 48 ms
[2020-05-04 10:13:53] DEBUG policy.generation.timing - Paths computed and templates read in 198 ms
[2020-05-04 10:14:05] DEBUG policy.generation.timing - Policy templates prepared in 11447 ms
[2020-05-04 10:14:05] TRACE policy.generation.timing -  -> bundle sequence built in 11237 ms | agent system variables built in 293 ms | policy template prepared in 44596 ms
[2020-05-04 10:21:12] DEBUG policy.generation.timing - Policies written in 427272 ms
[2020-05-04 10:21:12] TRACE policy.generation.timing -  -> fill template: 229788 ms [fill template: 55594 ms | to string template: 169540 ms | fill template wait: 0 ms | get template exec: 101 ms | get template wait: 0 ms]
[2020-05-04 10:21:12] TRACE policy.generation.timing -  -> write template: 291822 ms | copy resources: 131209 ms | agent specific: 230 ms | write CSV: 12349 ms| write JSON: 28133 ms
[2020-05-04 10:21:12] DEBUG policy.generation.timing - Getting info for timing trace in 0 ms
[2020-05-04 10:21:14] DEBUG policy.generation.timing - Properties written in 1700 ms
[2020-05-04 10:21:14] DEBUG policy.generation.timing - Parameters written in 386 ms
[2020-05-04 10:21:31] DEBUG policy.generation.timing.hooks - Hooks for policy-generation-node-ready executed in 17059 ms
[2020-05-04 10:21:31] DEBUG policy.generation - Using atomic move for node policies
[2020-05-04 10:22:17] DEBUG policy.generation.timing - Policies moved to their final position in 45986 ms
[2020-05-04 10:22:17] DEBUG policy.generation.timing.hooks - Hooks for policy-generation-node-finished executed in 440 ms
[2020-05-04 10:22:17] DEBUG policy.generation.timing - Node configuration written on filesystem in 504565 ms
[2020-05-04 10:22:34] DEBUG policy.generation.timing - Node configuration cached in LDAP in 16296 ms
[2020-05-04 10:22:34] DEBUG policy.generation.timing - Node configuration written in 520864 ms, start to update expected reports.
[2020-05-04 10:22:36] DEBUG policy.generation.timing - Reports computed in 2265 ms
[2020-05-04 10:23:16] DEBUG policy.generation.timing - Node expected reports saved in base in 39965 ms.
[2020-05-04 10:23:16] 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 10:23:16] DEBUG policy.generation.timing - Post-policy-generation hooks ran in 501 ms
[2020-05-04 10:23:16] INFO  policy.generation.timing - Timing summary:
[2020-05-04 10:23:16] INFO  policy.generation.timing - Run pre-gen scripts hooks     :         19 ms
[2020-05-04 10:23:16] INFO  policy.generation.timing - Run pre-gen modules hooks     :          0 ms
[2020-05-04 10:23:16] INFO  policy.generation.timing - Fetch all information         :       4794 ms
[2020-05-04 10:23:16] INFO  policy.generation.timing - Historize names               :      10173 ms
[2020-05-04 10:23:16] INFO  policy.generation.timing - Build current rule values     :       3021 ms
[2020-05-04 10:23:16] INFO  policy.generation.timing - Build target configuration    :     137671 ms
[2020-05-04 10:23:16] INFO  policy.generation.timing - Write node configurations     :     520864 ms
[2020-05-04 10:23:16] INFO  policy.generation.timing - Save expected reports         :       2265 ms
[2020-05-04 10:23:16] INFO  policy.generation.timing - Run post generation hooks     :        501 ms
[2020-05-04 10:23:16] INFO  policy.generation.timing - Number of nodes updated       :       4551   
[2020-05-04 10:23:16] INFO  policy.generation.timing - Policy generation succeeded in: 13 min 14 s

Actions

Also available in: Atom PDF