[CFE-2162] Iteration over slists or containers is extremely slow - Northern.tech AS

XML

Word

Printable

Details

Type: Bug
Status: Done
Priority: High
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 3.10.0
Component/s: Evaluation
Labels:
- performance

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

Options
- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

Attachments

champagne.png
153 kB
29/Sep/16 11:40 PM
eval_test.tar
6 kB
28/Jun/16 7:49 PM
locations.json
7 kB
13/Oct/15 9:04 PM
looping.cf
0.7 kB
13/Oct/15 9:04 PM
slow-simple-2.cf
0.5 kB
15/Apr/16 2:34 PM
t.cf
0.6 kB
24/Mar/16 8:39 PM

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

(12 relates to)

Activity

People

Assignee:: jimis (Dimitrios Apostolou)

Reporter:: Marco Marongiu

Votes:: 4 Vote for this issue

Watchers:: 12 Start watching this issue

Dates

Created:: 13/Oct/15 9:08 PM

Updated:: 28/Oct/21 6:13 PM

Resolved:: 04/Nov/16 4:17 PM