Uploaded image for project: 'CFEngine Community'
  1. CFEngine Community
  2. CFE-2162

Iteration over slists or containers is extremely slow

    Details

    • External issue ID:
      7631
    • Sprint:
      MEN Sprint 7, MEN Sprint 8, MEN Sprint 9, MEN Sprint 10, MEN Sprint 17, MEN Sprint 18
    • Story Points:
      34
    • Platform (OS, compiler):
      Debian GNU/Linux 8.2 "Jessie"
    • Platform:
      Debian

      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

        1. champagne.png
          champagne.png
          153 kB
        2. eval_test.tar
          6 kB
        3. locations.json
          7 kB
        4. looping.cf
          0.7 kB
        5. slow-simple-2.cf
          0.5 kB
        6. t.cf
          0.6 kB

          Container Issues

            Issue Links

              Activity

                People

                • Assignee:
                  a10038 jimis (Dimitrios Apostolou)
                  Reporter:
                  bronto Marco Marongiu
                • Votes:
                  4 Vote for this issue
                  Watchers:
                  12 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved:

                    Zendesk Support

                      Summary Panel