Actions
Bug #17315
closed
policy generation - writing file - doesn't seem parralelised
Pull Request:
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
Updated by Nicolas CHARLES about 4 years ago
- Related to Bug #17214: chmod at the end of policy generation is painfully slow added
Updated by Nicolas CHARLES about 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
Updated by Vincent MEMBRÉ about 4 years ago
- Target version changed from 6.1.0~beta2 to 6.1.0~beta3
Updated by Nicolas CHARLES about 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