Details
-
Type:
Bug
-
Status: Done
-
Priority:
High
-
Resolution: Fixed
-
Affects Version/s: None
-
Fix Version/s: 3.10.0
-
Component/s: Evaluation
-
Labels:
-
Story Points:34
Description
This problem was talked about in a "thread in the help-cfengine mailing list":https://groups.google.com/d/msg/help-cfengine/jb7Pjbe03Rw/quvQPskDCQAJ
I'm hitting hard performance problems at compile time (cf-promises) trying to fill up arrays from a data container; I am forced to copy data from containers over to arrays because there is no way to extract some substructures from the data container into a single array (like, e.g., one would do with XPath on an XML structure).
I have a "library" that puts together network ranges and information about said ranges to provide location detection and consistent information that can be used elsewhere; for example: you can get the list of certain IPv4 networks in Oslo and create iptables rules that will allow access for those addresses, while also providing a comment that will tell someone inspecting the output of iptables what those ranges represent.
When I decided to rework the library, I decided to put most of the IP/location information in a JSON file so that I had a single authoritative source to use in different parts of the policy. The JSON structure is a list of the following:
location_class: { id: "string identifier for this location", ranges: { "ip range" : "string identifier for this range", ...more ranges... }, ...more locations...
e.g.
"oslo_office": { id : "Norway/Oslo/Office", ranges: { "1.2.3.0/24" : "An imaginary network of the Oslo office", "1.1.0.0/16" : "A very big imaginary network in the Oslo office" },
When I tried to build an array to associate each range with it's description by reading that information from the data container, I couldn't get it done: with 59 IPv6 ranges and 42 IPv4 ranges, filling the array takes f-o-r-e-v-e-r.
When running cf-promises on the attached test policy and data file, I get this:
bronto@brabham:~/Downloads/looping-cf$ time sudo cf-promises -vC -f ./looping.cf 2015-10-13T11:50:12+0200 verbose: Could not open extension plugin 'cfengine-enterprise.so' from '/var/cfengine/lib/cfengine-enterprise.so': (not installed) 2015-10-13T11:50:12+0200 verbose: Setting cfengine default port to 5308 2015-10-13T11:50:12+0200 verbose: Work directory is /var/cfengine 2015-10-13T11:50:12+0200 verbose: Looking for a source of entropy in '/var/cfengine/randseed' 2015-10-13T11:50:12+0200 verbose: Making sure that internal directories are private... 2015-10-13T11:50:12+0200 verbose: Checking integrity of the trusted workdir 2015-10-13T11:50:12+0200 verbose: Checking integrity of the state database 2015-10-13T11:50:12+0200 verbose: Checking integrity of the module directory 2015-10-13T11:50:12+0200 verbose: Checking integrity of the PKI directory 2015-10-13T11:50:12+0200 verbose: Loaded private key at '/var/cfengine/ppkeys/localhost.priv' 2015-10-13T11:50:12+0200 verbose: Loaded public key '/var/cfengine/ppkeys/localhost.pub' 2015-10-13T11:50:12+0200 verbose: Reference time set to 'Tue Oct 13 11:50:12 2015' 2015-10-13T11:50:12+0200 verbose: CFEngine Core 3.6.6 2015-10-13T11:50:12+0200 verbose: Host name is: brabham 2015-10-13T11:50:12+0200 verbose: Operating System Type is linux 2015-10-13T11:50:12+0200 verbose: Operating System Release is 3.16.0-4-amd64 2015-10-13T11:50:12+0200 verbose: Architecture = x86_64 2015-10-13T11:50:12+0200 verbose: Using internal soft-class linux for host brabham 2015-10-13T11:50:12+0200 verbose: The time is now Tue Oct 13 11:50:12 2015 2015-10-13T11:50:12+0200 verbose: Additional hard class defined as: 64_bit 2015-10-13T11:50:12+0200 verbose: Additional hard class defined as: linux_3_16_0_4_amd64 2015-10-13T11:50:12+0200 verbose: Additional hard class defined as: linux_x86_64 2015-10-13T11:50:12+0200 verbose: Additional hard class defined as: linux_x86_64_3_16_0_4_amd64 2015-10-13T11:50:12+0200 verbose: GNU autoconf class from compile time: compiled_on_linux_gnu 2015-10-13T11:50:12+0200 verbose: Address given by nameserver: 127.0.1.1 2015-10-13T11:50:12+0200 verbose: No interface exception file /var/cfengine/inputs/ignore_interfaces.rx 2015-10-13T11:50:12+0200 verbose: Interface 1: lo 2015-10-13T11:50:12+0200 verbose: Interface 2: eth0
...cut ip addresses...
2015-10-13T11:50:12+0200 verbose: Looking for environment from cf-monitord... 2015-10-13T11:50:12+0200 verbose: Loading environment... 2015-10-13T11:50:12+0200 verbose: Environment data loaded 2015-10-13T11:50:12+0200 verbose: Extended system discovery is only available in CFEngine Enterprise 2015-10-13T11:50:12+0200 verbose: This appears to be a debian system. 2015-10-13T11:50:12+0200 verbose: Looking for Debian version... 2015-10-13T11:50:12+0200 verbose: This appears to be a Debian 8.2 system. 2015-10-13T11:50:12+0200 verbose: This system seems to have the aptitude package system 2015-10-13T11:50:12+0200 verbose: Found 8 processors 2015-10-13T11:50:12+0200 verbose: Persistent class 'cpu1_high_ldt' for 4 more minutes 2015-10-13T11:50:12+0200 verbose: Adding persistent class 'cpu1_high_ldt' to heap 2015-10-13T11:50:12+0200 verbose: Persistent class 'messages_low_anomaly' for 2 more minutes 2015-10-13T11:50:12+0200 verbose: Adding persistent class 'messages_low_anomaly' to heap 2015-10-13T11:50:12+0200 verbose: Persistent class 'messages_low_dev2' for 2 more minutes 2015-10-13T11:50:12+0200 verbose: Adding persistent class 'messages_low_dev2' to heap 2015-10-13T11:50:12+0200 verbose: Persistent class 'syslog_low_anomaly' for 2 more minutes 2015-10-13T11:50:12+0200 verbose: Adding persistent class 'syslog_low_anomaly' to heap 2015-10-13T11:50:12+0200 verbose: Persistent class 'syslog_low_dev2' for 2 more minutes 2015-10-13T11:50:12+0200 verbose: Adding persistent class 'syslog_low_dev2' to heap 2015-10-13T11:50:12+0200 verbose: This agent is not bootstrapped 2015-10-13T11:50:12+0200 verbose: Parsing file './looping.cf' 2015-10-13T11:50:12+0200 verbose: /default/test/vars: Evaluating promise 'data' 2015-10-13T11:50:12+0200 verbose: /default/test/vars: Evaluating promise 'classes' 2015-10-13T11:50:12+0200 verbose: /default/test/vars: Evaluating promise 'ranges[$(classes)]' 2015-10-13T11:50:12+0200 verbose: /default/test/vars: Evaluating promise 'desc[$(ranges[$(classes)])]'
and there it hangs, one CPU thread at 100%. gdb returns this:
bronto@brabham:~$ for I in {1..5} ; do echo "GDB run #$I" ; sudo gdb -q -n -batch -p 9265 -ex "backtrace" ; echo "=== END RUN #$I ===" ; echo ; sleep 5 ; done GDB run #1 [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". __GI___libc_free (mem=0x12259d0) at malloc.c:2918 2918 malloc.c: No such file or directory. #0 __GI___libc_free (mem=0x12259d0) at malloc.c:2918 #1 0x00007faafde72678 in EvalContextVariablePutSpecial (ctx=0x1171110, scope=<optimized out>, lval=<optimized out>, value=0x120d160, type=CF_DATA_TYPE_STRING, tags=0x7faafdecc9fa "source=promise") at eval_context.c:1546 #2 0x00007faafde8bff6 in PromiseIteratorUpdateVariable (ctx=0x1171110, iter=0x11eff80) at iteration.c:447 #3 0x00007faafde72dd3 in EvalContextStackPushPromiseIterationFrame (ctx=0x1171110, iteration_index=31263326, iter_ctx=0x7faafcb95628 <main_arena+8>) at eval_context.c:1167 #4 0x00007faafde83dd4 in ExpandPromiseAndDo (param=<optimized out>, ActOnPromise=<optimized out>, containers=0x6e, lists=0x12237d0, pp=<optimized out>, ctx=<optimized out>) at expand.c:199 #5 ExpandPromise (ctx=0x1171110, pp=<optimized out>, ActOnPromise=0x7faafdea4ad0 <VerifyVarPromise>, param=0x0) at expand.c:161 #6 0x00007faafde83ecb in BundleResolvePromiseType (ctx=0x1171110, bundle=0x11e8f90, type=0x7faafdeccc2b "vars", actuator=0x7faafdea4ad0 <VerifyVarPromise>) at expand.c:909 #7 0x00007faafde84073 in PolicyResolve (ctx=0x1171110, policy=0x11d3740, config=0x1171010) at expand.c:1089 #8 0x00007faafde8e1f0 in LoadPolicyFile (ctx=0x1171110, config=0x1171010, policy_file=0x11710d0 "./looping.cf", parsed_files_and_checksums=0x11d25f0, failed_files=0x11d35f0) at loading.c:347 #9 0x00007faafde8e5e3 in LoadPolicy (ctx=0x1171110, config=0x1171010) at loading.c:471 #10 0x00000000004022f8 in main (argc=0, argv=0x7ffdae0b4688) at cf-promises.c:129 === END RUN #1 === GDB run #2 [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". 0x00007faafdea2762 in VarRefParseFromNamespaceAndScope (qualified_name=<optimized out>, _ns=0x0, _scope=0x7faafded28b2 "this", ns_separator=<optimized out>, scope_separator=<optimized out>) at var_expressions.c:280 280 var_expressions.c: No such file or directory. #0 0x00007faafdea2762 in VarRefParseFromNamespaceAndScope (qualified_name=<optimized out>, _ns=0x0, _scope=0x7faafded28b2 "this", ns_separator=<optimized out>, scope_separator=<optimized out>) at var_expressions.c:280 #1 0x00007faafde72657 in EvalContextVariablePutSpecial (ctx=0x1171110, scope=SPECIAL_SCOPE_THIS, lval=0x120e1c0 "data[group2_private][ranges][10.25.0.0/16]", value=0x120e170, type=CF_DATA_TYPE_STRING, tags=0x7faafdecc9fa "source=promise") at eval_context.c:1544 #2 0x00007faafde8bff6 in PromiseIteratorUpdateVariable (ctx=0x1171110, iter=0x11eff80) at iteration.c:447 #3 0x00007faafde72dd3 in EvalContextStackPushPromiseIterationFrame (ctx=0x1171110, iteration_index=31290642, iter_ctx=0x31) at eval_context.c:1167 #4 0x00007faafde83dd4 in ExpandPromiseAndDo (param=<optimized out>, ActOnPromise=<optimized out>, containers=0x6e, lists=0x12237d0, pp=<optimized out>, ctx=<optimized out>) at expand.c:199 #5 ExpandPromise (ctx=0x1171110, pp=<optimized out>, ActOnPromise=0x7faafdea4ad0 <VerifyVarPromise>, param=0x0) at expand.c:161 #6 0x00007faafde83ecb in BundleResolvePromiseType (ctx=0x1171110, bundle=0x11e8f90, type=0x7faafdeccc2b "vars", actuator=0x7faafdea4ad0 <VerifyVarPromise>) at expand.c:909 #7 0x00007faafde84073 in PolicyResolve (ctx=0x1171110, policy=0x11d3740, config=0x1171010) at expand.c:1089 #8 0x00007faafde8e1f0 in LoadPolicyFile (ctx=0x1171110, config=0x1171010, policy_file=0x11710d0 "./looping.cf", parsed_files_and_checksums=0x11d25f0, failed_files=0x11d35f0) at loading.c:347 #9 0x00007faafde8e5e3 in LoadPolicy (ctx=0x1171110, config=0x1171010) at loading.c:471 #10 0x00000000004022f8 in main (argc=0, argv=0x7ffdae0b4688) at cf-promises.c:129 === END RUN #2 === GDB run #3 [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". _int_malloc (av=av@entry=0x7faafcb95620 <main_arena>, bytes=bytes@entry=24) at malloc.c:3743 3743 malloc.c: No such file or directory. #0 _int_malloc (av=av@entry=0x7faafcb95620 <main_arena>, bytes=bytes@entry=24) at malloc.c:3743 #1 0x00007faafc86ea2c in __libc_calloc (n=<optimized out>, elem_size=<optimized out>) at malloc.c:3219 #2 0x00007faafdea6f79 in xcalloc (nmemb=19045392, size=140372361172512) at alloc.c:47 #3 0x00007faafde90bc3 in ParsePrimary (expr=<optimized out>, start=<optimized out>, end=<optimized out>) at logic_expressions.c:67 #4 0x00007faafde90c7d in ParseNotExpression (end=<optimized out>, start=<optimized out>, expr=<optimized out>) at logic_expressions.c:105 #5 ParseAndExpression (expr=0x11f6550 "any", start=-54962656, end=-54962648) at logic_expressions.c:116 #6 0x00007faafde90dbd in ParseExpression (expr=0x1229c10 "\240\233\"\001", start=-54962656, end=-54962648) at logic_expressions.c:152 #7 0x00007faafde73d17 in IsDefinedClass (ctx=0x1171110, context=0x11f6550 "any") at eval_context.c:362 #8 0x00007faafde9b49e in EvaluateConstraintIteration (ctx=0x1229c10, cp=0x11f6e40, rval_out=0x7faafcb95628 <main_arena+8>) at promises.c:256 #9 0x00007faafde9b782 in ExpandDeRefPromise (ctx=0x1171110, pp=0x1202ed0, excluded=<optimized out>) at promises.c:410 #10 0x00007faafde72df3 in EvalContextStackPushPromiseIterationFrame (ctx=0x1171110, iteration_index=31318050, iter_ctx=0x11eff80) at eval_context.c:1171 #11 0x00007faafde83dd4 in ExpandPromiseAndDo (param=<optimized out>, ActOnPromise=<optimized out>, containers=0x6e, lists=0x12237d0, pp=<optimized out>, ctx=<optimized out>) at expand.c:199 #12 ExpandPromise (ctx=0x1171110, pp=<optimized out>, ActOnPromise=0x7faafdea4ad0 <VerifyVarPromise>, param=0x0) at expand.c:161 #13 0x00007faafde83ecb in BundleResolvePromiseType (ctx=0x1171110, bundle=0x11e8f90, type=0x7faafdeccc2b "vars", actuator=0x7faafdea4ad0 <VerifyVarPromise>) at expand.c:909 #14 0x00007faafde84073 in PolicyResolve (ctx=0x1171110, policy=0x11d3740, config=0x1171010) at expand.c:1089 #15 0x00007faafde8e1f0 in LoadPolicyFile (ctx=0x1171110, config=0x1171010, policy_file=0x11710d0 "./looping.cf", parsed_files_and_checksums=0x11d25f0, failed_files=0x11d35f0) at loading.c:347 #16 0x00007faafde8e5e3 in LoadPolicy (ctx=0x1171110, config=0x1171010) at loading.c:471 #17 0x00000000004022f8 in main (argc=0, argv=0x7ffdae0b4688) at cf-promises.c:129 === END RUN #3 === GDB run #4 [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". 0x00007faafdead131 in BufferAppend (buffer=0x1228340, bytes=0x1208fa9 "23::/64]", length=1) at buffer.c:248 248 buffer.c: No such file or directory. #0 0x00007faafdead131 in BufferAppend (buffer=0x1228340, bytes=0x1208fa9 "23::/64]", length=1) at buffer.c:248 #1 0x00007faafdea275e in VarRefParseFromNamespaceAndScope (qualified_name=<optimized out>, _ns=0x0, _scope=0x7faafded28b2 "this", ns_separator=<optimized out>, scope_separator=<optimized out>) at var_expressions.c:300 #2 0x00007faafde72657 in EvalContextVariablePutSpecial (ctx=0x1171110, scope=SPECIAL_SCOPE_THIS, lval=0x1208f80 "data[group2_ipv6][ranges][dead:beef:cafe:23::/64]", value=0x1208f30, type=CF_DATA_TYPE_STRING, tags=0x7faafdecc9fa "source=promise") at eval_context.c:1544 #3 0x00007faafde8bff6 in PromiseIteratorUpdateVariable (ctx=0x1171110, iter=0x11eff80) at iteration.c:447 #4 0x00007faafde72dd3 in EvalContextStackPushPromiseIterationFrame (ctx=0x1171110, iteration_index=31345388, iter_ctx=0x1) at eval_context.c:1167 #5 0x00007faafde83dd4 in ExpandPromiseAndDo (param=<optimized out>, ActOnPromise=<optimized out>, containers=0x6e, lists=0x12237d0, pp=<optimized out>, ctx=<optimized out>) at expand.c:199 #6 ExpandPromise (ctx=0x1171110, pp=<optimized out>, ActOnPromise=0x7faafdea4ad0 <VerifyVarPromise>, param=0x0) at expand.c:161 #7 0x00007faafde83ecb in BundleResolvePromiseType (ctx=0x1171110, bundle=0x11e8f90, type=0x7faafdeccc2b "vars", actuator=0x7faafdea4ad0 <VerifyVarPromise>) at expand.c:909 #8 0x00007faafde84073 in PolicyResolve (ctx=0x1171110, policy=0x11d3740, config=0x1171010) at expand.c:1089 #9 0x00007faafde8e1f0 in LoadPolicyFile (ctx=0x1171110, config=0x1171010, policy_file=0x11710d0 "./looping.cf", parsed_files_and_checksums=0x11d25f0, failed_files=0x11d35f0) at loading.c:347 #10 0x00007faafde8e5e3 in LoadPolicy (ctx=0x1171110, config=0x1171010) at loading.c:471 #11 0x00000000004022f8 in main (argc=0, argv=0x7ffdae0b4688) at cf-promises.c:129 === END RUN #4 === GDB run #5 [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". 0x00007faafc86bde3 in _int_malloc (av=0x7faafcb95620 <main_arena>, bytes=24) at malloc.c:3351 3351 malloc.c: No such file or directory. #0 0x00007faafc86bde3 in _int_malloc (av=0x7faafcb95620 <main_arena>, bytes=24) at malloc.c:3351 #1 0x00007faafc86e070 in __GI___libc_malloc (bytes=24) at malloc.c:2891 #2 0x00007faafdea6fb9 in xmalloc (size=19039024) at alloc.c:42 #3 0x00007faafdea2722 in VarRefParseFromNamespaceAndScope (qualified_name=0x1208070 "data[group1_ipv6][ranges][dead:beef:cafe:12::/64]", _ns=0x0, _scope=0x7faafded28b2 "this", ns_separator=<optimized out>, scope_separator=<optimized out>) at var_expressions.c:274 #4 0x00007faafde72657 in EvalContextVariablePutSpecial (ctx=0x1171110, scope=SPECIAL_SCOPE_THIS, lval=0x1208070 "data[group1_ipv6][ranges][dead:beef:cafe:12::/64]", value=0x1208020, type=CF_DATA_TYPE_STRING, tags=0x7faafdecc9fa "source=promise") at eval_context.c:1544 #5 0x00007faafde8bff6 in PromiseIteratorUpdateVariable (ctx=0x1171110, iter=0x11eff80) at iteration.c:447 #6 0x00007faafde72dd3 in EvalContextStackPushPromiseIterationFrame (ctx=0x1171110, iteration_index=31372789, iter_ctx=0x7faafcb95628 <main_arena+8>) at eval_context.c:1167 #7 0x00007faafde83dd4 in ExpandPromiseAndDo (param=<optimized out>, ActOnPromise=<optimized out>, containers=0x6e, lists=0x12237d0, pp=<optimized out>, ctx=<optimized out>) at expand.c:199 #8 ExpandPromise (ctx=0x1171110, pp=<optimized out>, ActOnPromise=0x7faafdea4ad0 <VerifyVarPromise>, param=0x0) at expand.c:161 #9 0x00007faafde83ecb in BundleResolvePromiseType (ctx=0x1171110, bundle=0x11e8f90, type=0x7faafdeccc2b "vars", actuator=0x7faafdea4ad0 <VerifyVarPromise>) at expand.c:909 #10 0x00007faafde84073 in PolicyResolve (ctx=0x1171110, policy=0x11d3740, config=0x1171010) at expand.c:1089 #11 0x00007faafde8e1f0 in LoadPolicyFile (ctx=0x1171110, config=0x1171010, policy_file=0x11710d0 "./looping.cf", parsed_files_and_checksums=0x11d25f0, failed_files=0x11d35f0) at loading.c:347 #12 0x00007faafde8e5e3 in LoadPolicy (ctx=0x1171110, config=0x1171010) at loading.c:471 #13 0x00000000004022f8 in main (argc=0, argv=0x7ffdae0b4688) at cf-promises.c:129 === END RUN #5 === bronto@brabham:~$
It's all user time: when I interrupt the process the output of time is:
^C real 135m41.653s user 135m44.488s sys 0m0.000s bronto@brabham:~/Downloads/looping-cf$
To me, it looks like the agent/parser is having a really hard time in descending into the structure of the data container, to the point that it brings the whole process to its knee. I think that's a pretty bad problem because the data structures are not that clumsy to justify such inefficiencies. I believe that every CFEngine user would appreciate this matter to be fixed as soon as possible (for small values of soon and possible .
Ciao
– bronto
Attachments
Release management
Issue Links
- is duplicated by
-
CFE-1307 cf-promises goes into infinite loop when iterating over an array of lists
-
- Done
-
-
CFE-1801 Long slists are very slow to parse
-
- Rejected
-
- relates to
-
CFE-1779 Iteration over referenced list does not work
-
- Open
-
-
CFE-2232 Should be able to define variables from non null keys in data
-
- Open
-
-
CFE-1931 using format() on lists produces --empty-list--
-
- Open
-
-
CFE-2433 Why is it more efficient to actuate bundles from body common control than as methods type promises
-
- Open
-
-
CFE-1307 cf-promises goes into infinite loop when iterating over an array of lists
-
- Done
-
-
CFE-2071 mapdata support for jq mode
-
- Done
-
-
CFE-2077 cf_null appears in expanded mustache template when using data containers, slists and difference
-
- Done
-
-
CFE-1833 cf-promises/cf-agent uses 100% CPU for minutes in variable enumeration
-
- Unconfirmed
-
-
CFE-2226 new packages promise: empty list gets still processed
-
- Unconfirmed
-
-
CFE-1944 Variable in called bundle retains its value from previous call when attempting to assign null value
-
- Rejected
-
-
CFE-1583 Nested expansion of variables including namespace does not work
-
- Done
-
-
CFE-1780 Classes set in common bundles using variables on the RHS are not available early enough for dynamic inputs
-
- Done
-
-
CFE-2460 Append bundles to the bundlesequence without having to modify any shipped files in the MPF
-
- Done
-
-
CFE-2397 Segfault when constructing array with getindices()
-
- Done
-
-
CFE-2306 Possible performance issue with many variables
-
- Done
-