[PATCH] event: Fix multiconfig event handler change performance regressions

[PATCH] event: Fix multiconfig event handler change performance regressions

[Richard Purdie]

There were two issues in this code, firstly the code could stack duplicates
in the variable, secondly, calling "if data" caused the datastore to compute
len(data) which is comparitively expensive. Checking "if data is not None"
is much much faster/cheaper.

The issue was clear from "bitbake -p -P" output where the time in register()
showed large amounts of time in the __len__ function of the datastore.

Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
---
 lib/bb/event.py | 22 +++++++++++-----------
 1 file changed, 11 insertions(+), 11 deletions(-)

diff --git a/lib/bb/event.py b/lib/bb/event.py
index 3e5718395b..22171a9ca5 100644
--- a/lib/bb/event.py
+++ b/lib/bb/event.py
@@ -118,7 +118,7 @@ def fire_class_handlers(event, d):
             if _eventfilter:
                 if not _eventfilter(name, handler, event, d):
                     continue
-            if d and not name in (d.getVar("__BBHANDLERS_MC") or []):
+            if d and not name in (d.getVar("__BBHANDLERS_MC") or set()):
                 continue
             execute_handler(name, handler, event, d)
 
@@ -232,15 +232,15 @@ noop = lambda _: None
 def register(name, handler, mask=None, filename=None, lineno=None, data=None):
     """Register an Event handler"""
 
-    if data and data.getVar("BB_CURRENT_MC"):
+    if data is not None and data.getVar("BB_CURRENT_MC"):
         mc = data.getVar("BB_CURRENT_MC")
         name = '%s%s' % (mc.replace('-', '_'), name)
 
     # already registered
     if name in _handlers:
-        if data:
-            bbhands_mc = (data.getVar("__BBHANDLERS_MC") or [])
-            bbhands_mc.append(name)
+        if data is not None:
+            bbhands_mc = (data.getVar("__BBHANDLERS_MC") or set())
+            bbhands_mc.add(name)
             data.setVar("__BBHANDLERS_MC", bbhands_mc)
         return AlreadyRegistered
 
@@ -278,16 +278,16 @@ def register(name, handler, mask=None, filename=None, lineno=None, data=None):
                     _event_handler_map[m] = {}
                 _event_handler_map[m][name] = True
 
-        if data:
-            bbhands_mc = (data.getVar("__BBHANDLERS_MC") or [])
-            bbhands_mc.append(name)
+        if data is not None:
+            bbhands_mc = (data.getVar("__BBHANDLERS_MC") or set())
+            bbhands_mc.add(name)
             data.setVar("__BBHANDLERS_MC", bbhands_mc)
 
         return Registered
 
 def remove(name, handler, data=None):
     """Remove an Event handler"""
-    if data:
+    if data is not None:
         if data.getVar("BB_CURRENT_MC"):
             mc = data.getVar("BB_CURRENT_MC")
             name = '%s%s' % (mc.replace('-', '_'), name)
@@ -299,8 +299,8 @@ def remove(name, handler, data=None):
         if name in _event_handler_map[event]:
             _event_handler_map[event].pop(name)
 
-    if data:
-        bbhands_mc = (data.getVar("__BBHANDLERS_MC") or [])
+    if data is not None:
+        bbhands_mc = (data.getVar("__BBHANDLERS_MC") or set())
         if name in bbhands_mc:
             bbhands_mc.remove(name)
             data.setVar("__BBHANDLERS_MC", bbhands_mc)
-- 
2.27.0

Re: [bitbake-devel] [PATCH] event: Fix multiconfig event handler change performance regressions

[Christopher Larson]

[-- Attachment #1: Type: text/plain, Size: 1394 bytes --]

On Thu, Mar 11, 2021 at 6:46 AM Richard Purdie <
richard.purdie@linuxfoundation.org> wrote:

> There were two issues in this code, firstly the code could stack duplicates
> in the variable, secondly, calling "if data" caused the datastore to
> compute
> len(data) which is comparitively expensive. Checking "if data is not None"
> is much much faster/cheaper.
>
> The issue was clear from "bitbake -p -P" output where the time in
> register()
> showed large amounts of time in the __len__ function of the datastore.
>
> Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
> ---
>  lib/bb/event.py | 22 +++++++++++-----------
>  1 file changed, 11 insertions(+), 11 deletions(-)
>
> diff --git a/lib/bb/event.py b/lib/bb/event.py
> index 3e5718395b..22171a9ca5 100644
> --- a/lib/bb/event.py
> +++ b/lib/bb/event.py
> @@ -118,7 +118,7 @@ def fire_class_handlers(event, d):
>              if _eventfilter:
>                  if not _eventfilter(name, handler, event, d):
>                      continue
> -            if d and not name in (d.getVar("__BBHANDLERS_MC") or []):
> +            if d and not name in (d.getVar("__BBHANDLERS_MC") or set()):
>

Shouldn't this one also be doing a 'is not None' check?
-- 
Christopher Larson
kergoth at gmail dot com
Founder - BitBake, OpenEmbedded, OpenZaurus
Senior Software Engineer, Mentor Graphics

[-- Attachment #2: Type: text/html, Size: 2058 bytes --]

Re: [bitbake-devel] [PATCH] event: Fix multiconfig event handler change performance regressions

[Peter Kjellerstedt]

[-- Attachment #1: Type: text/plain, Size: 5452 bytes --]

> -----Original Message-----
> From: bitbake-devel@lists.openembedded.org <bitbake-
> devel@lists.openembedded.org> On Behalf Of Richard Purdie
> Sent: den 11 mars 2021 14:46
> To: bitbake-devel@lists.openembedded.org
> Subject: [bitbake-devel] [PATCH] event: Fix multiconfig event handler
> change performance regressions
> 
> There were two issues in this code, firstly the code could stack
> duplicates
> in the variable, secondly, calling "if data" caused the datastore to
> compute
> len(data) which is comparitively expensive. Checking "if data is not None"
> is much much faster/cheaper.
> 
> The issue was clear from "bitbake -p -P" output where the time in
> register()
> showed large amounts of time in the __len__ function of the datastore.
> 
> Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
> ---
>  lib/bb/event.py | 22 +++++++++++-----------
>  1 file changed, 11 insertions(+), 11 deletions(-)
> 
> diff --git a/lib/bb/event.py b/lib/bb/event.py
> index 3e5718395b..22171a9ca5 100644
> --- a/lib/bb/event.py
> +++ b/lib/bb/event.py
> @@ -118,7 +118,7 @@ def fire_class_handlers(event, d):
>              if _eventfilter:
>                  if not _eventfilter(name, handler, event, d):
>                      continue
> -            if d and not name in (d.getVar("__BBHANDLERS_MC") or []):
> +            if d and not name in (d.getVar("__BBHANDLERS_MC") or set()):
>                  continue
>              execute_handler(name, handler, event, d)
> 
> @@ -232,15 +232,15 @@ noop = lambda _: None
>  def register(name, handler, mask=None, filename=None, lineno=None,
> data=None):
>      """Register an Event handler"""
> 
> -    if data and data.getVar("BB_CURRENT_MC"):
> +    if data is not None and data.getVar("BB_CURRENT_MC"):
>          mc = data.getVar("BB_CURRENT_MC")
>          name = '%s%s' % (mc.replace('-', '_'), name)
> 
>      # already registered
>      if name in _handlers:
> -        if data:
> -            bbhands_mc = (data.getVar("__BBHANDLERS_MC") or [])
> -            bbhands_mc.append(name)
> +        if data is not None:
> +            bbhands_mc = (data.getVar("__BBHANDLERS_MC") or set())
> +            bbhands_mc.add(name)
>              data.setVar("__BBHANDLERS_MC", bbhands_mc)
>          return AlreadyRegistered
> 
> @@ -278,16 +278,16 @@ def register(name, handler, mask=None,
> filename=None, lineno=None, data=None):
>                      _event_handler_map[m] = {}
>                  _event_handler_map[m][name] = True
> 
> -        if data:
> -            bbhands_mc = (data.getVar("__BBHANDLERS_MC") or [])
> -            bbhands_mc.append(name)
> +        if data is not None:
> +            bbhands_mc = (data.getVar("__BBHANDLERS_MC") or set())
> +            bbhands_mc.add(name)
>              data.setVar("__BBHANDLERS_MC", bbhands_mc)
> 
>          return Registered
> 
>  def remove(name, handler, data=None):
>      """Remove an Event handler"""
> -    if data:
> +    if data is not None:
>          if data.getVar("BB_CURRENT_MC"):
>              mc = data.getVar("BB_CURRENT_MC")
>              name = '%s%s' % (mc.replace('-', '_'), name)
> @@ -299,8 +299,8 @@ def remove(name, handler, data=None):
>          if name in _event_handler_map[event]:
>              _event_handler_map[event].pop(name)
> 
> -    if data:
> -        bbhands_mc = (data.getVar("__BBHANDLERS_MC") or [])
> +    if data is not None:
> +        bbhands_mc = (data.getVar("__BBHANDLERS_MC") or set())
>          if name in bbhands_mc:
>              bbhands_mc.remove(name)
>              data.setVar("__BBHANDLERS_MC", bbhands_mc)
> --
> 2.27.0

While this greatly improves the situation, it is still not good. Here are some 
numbers for me when parsing poky + openembedded + our layers:

poky + openembedded + axis dunfell
Parsing recipes: 100% |###############################| Time: 0:00:39
Parsing of 3935 .bb files complete (0 cached, 3935 parsed). 
5767 targets, 711 skipped, 0 masked, 0 errors.

poky + openembedded + axis gatesgarth
Parsing recipes: 100% |###############################| Time: 0:00:39
Parsing of 4051 .bb files complete (0 cached, 4051 parsed). 
5490 targets, 726 skipped, 0 masked, 0 errors.

poky + openembedded + axis master
Parsing recipes: 100% |###############################| Time: 0:01:07
Parsing of 4111 .bb files complete (0 cached, 4111 parsed). 
5607 targets, 732 skipped, 12 masked, 0 errors.

And here are similar measurements with only the poky and openembedded layers 
(meta, meta-poky, meta-gplv2, meta-oe, meta-filesystems, meta-networking, 
meta-python and meta-webserver):

poky + openembedded gatesgarth
Parsing recipes: 100% |###############################| Time: 0:00:17
Parsing of 2289 .bb files complete (0 cached, 2289 parsed). 
3537 targets, 91 skipped, 0 masked, 0 errors.

poky + openembedded master
Parsing recipes: 100% |###############################| Time: 0:00:27
Parsing of 2354 .bb files complete (0 cached, 2354 parsed). 
3659 targets, 64 skipped, 0 masked, 0 errors.

I have attached profiling logs (first 40 lines) for a gatesgarth run and a 
master run. If I read the data correctly, it seems that during the master 
parsing, there are a lot of calls to fnmatch.translate, posix.read and 
_posixsubprocess.fork_exec that are not there during the gatesgarth parsing.

//Peter


[-- Attachment #2: profile-gatesgarth.txt --]
[-- Type: text/plain, Size: 3433 bytes --]

         1122347697 function calls (1095493286 primitive calls) in 815.166 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
23017966/13040498   57.931    0.000  339.036    0.000 bitbake/lib/bb/data_smart.py:689(getVarFlag)
204494029   52.456    0.000   52.456    0.000 {method 'match' of 're.Pattern' objects}
  1312593   38.940    0.000   38.940    0.000 {built-in method builtins.compile}
 48315261   31.128    0.000   61.383    0.000 bitbake/lib/bb/data_smart.py:938(__iter__)
 21886459   29.084    0.000   32.760    0.000 bitbake/lib/bb/data_smart.py:459(_findVar)
 12982153   27.503    0.000   27.504    0.000 bitbake/lib/bb/data_smart.py:83(__init__)
  3346928   25.480    0.000  233.149    0.000 bitbake/lib/bb/data.py:275(build_dependencies)
  1885073   25.195    0.000   38.652    0.000 /usr/lib64/python3.7/logging/__init__.py:1304(_clear_cache)
  6463751   24.997    0.000   37.335    0.000 /usr/lib64/python3.7/posixpath.py:338(normpath)
67926/11498   23.783    0.000   27.459    0.002 bitbake/lib/bb/data_smart.py:941(keylist)
12982153/8061609   21.807    0.000  309.199    0.000 bitbake/lib/bb/data_smart.py:391(expandWithRefs)
     4787   21.041    0.004   30.362    0.006 bitbake/lib/bb/data.py:400(generate_dependency_hash)
14198519/9801796   20.215    0.000  279.148    0.000 {method 'sub' of 're.Pattern' objects}
  1430108   19.688    0.000   67.529    0.000 /usr/lib64/python3.7/fnmatch.py:48(filter)
1281428/747365   15.402    0.000  223.862    0.000 bitbake/lib/bb/data_smart.py:104(python_sub)
115994320   15.340    0.000   15.351    0.000 {built-in method builtins.isinstance}
     4787   14.623    0.003  286.359    0.060 bitbake/lib/bb/data.py:374(generate_dependencies)
  2013230   11.945    0.000   11.945    0.000 {built-in method _hashlib.openssl_sha256}
  1518906   10.519    0.000   13.613    0.000 bitbake/lib/bb/data_smart.py:567(_setvar_update_overrides)
6300260/3690750   10.396    0.000  192.875    0.000 bitbake/lib/bb/data_smart.py:92(var_sub)
  1586613   10.294    0.000   30.569    0.000 bitbake/lib/bb/data_smart.py:482(setVar)
 57421134    9.613    0.000    9.613    0.000 {method 'startswith' of 'str' objects}
 25239454    9.256    0.000    9.256    0.000 {method 'split' of 'str' objects}
  3392496    8.590    0.000   27.694    0.000 bitbake/lib/bb/data_smart.py:861(getVarFlags)
 10726807    7.855    0.000   16.866    0.000 /usr/lib64/python3.7/copy.py:66(copy)
  1787226    7.821    0.000   18.278    0.000 bitbake/lib/bb/codeparser.py:284(parse_python)
  1787226    7.619    0.000   62.263    0.000 bitbake/lib/bb/codeparser.py:273(__init__)
  2599995    7.473    0.000    7.473    0.000 {built-in method posix.lstat}
 45799399    7.082    0.000    7.082    0.000 {method 'get' of 'dict' objects}
  8455928    6.712    0.000    6.712    0.000 {method 'copy' of 'dict' objects}
 12271775    6.200    0.000    9.444    0.000 /usr/lib64/python3.7/re.py:271(_compile)
  3470277    6.080    0.000    9.395    0.000 /usr/lib64/python3.7/posixpath.py:75(join)
 20013549    5.786    0.000   34.310    0.000 bitbake/lib/bb/data.py:376(<genexpr>)
    33621    5.442    0.000   28.731    0.001 meta/lib/oe/license.py:10(license_ok)
  1090729    5.409    0.000    5.409    0.000 {built-in method posix.stat}
 66814642    5.376    0.000    5.376    0.000 {method 'append' of 'list' objects}

[-- Attachment #3: profile-master.txt --]
[-- Type: text/plain, Size: 3480 bytes --]

         1918178338 function calls (1890825621 primitive calls) in 1264.416 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
473116959  108.179    0.000  108.179    0.000 {method 'match' of 're.Pattern' objects}
     9483   80.326    0.008   80.326    0.008 {built-in method posix.read}
 14136957   79.018    0.000  175.192    0.000 /usr/lib64/python3.7/fnmatch.py:74(translate)
25545206/15345830   63.981    0.000  490.773    0.000 bitbake/lib/bb/data_smart.py:689(getVarFlag)
139506392   47.590    0.000   94.568    0.000 /usr/lib64/python3.7/re.py:252(escape)
  2928540   45.902    0.000  189.106    0.000 /usr/lib64/python3.7/fnmatch.py:48(filter)
     3161   42.907    0.014   42.957    0.014 {built-in method _posixsubprocess.fork_exec}
  1350731   40.247    0.000   40.247    0.000 {built-in method builtins.compile}
139513699   36.409    0.000   36.409    0.000 {method 'translate' of 'str' objects}
 50686785   35.119    0.000   66.175    0.000 bitbake/lib/bb/data_smart.py:938(__iter__)
 15039367   35.095    0.000   35.095    0.000 bitbake/lib/bb/data_smart.py:83(__init__)
 24293007   32.747    0.000   36.549    0.000 bitbake/lib/bb/data_smart.py:459(_findVar)
277679495   29.849    0.000   29.849    0.000 {built-in method builtins.isinstance}
  7070886   26.526    0.000   39.592    0.000 /usr/lib64/python3.7/posixpath.py:338(normpath)
  3397212   25.549    0.000  335.705    0.000 bitbake/lib/bb/data.py:275(build_dependencies)
  1935019   25.017    0.000   38.180    0.000 /usr/lib64/python3.7/logging/__init__.py:1304(_clear_cache)
69288/11725   24.482    0.000   28.243    0.002 bitbake/lib/bb/data_smart.py:941(keylist)
15039367/9980415   23.376    0.000  453.103    0.000 bitbake/lib/bb/data_smart.py:391(expandWithRefs)
     4896   21.356    0.004   30.695    0.006 bitbake/lib/bb/data.py:400(generate_dependency_hash)
8312384/3825261   18.115    0.000  412.843    0.000 {method 'sub' of 're.Pattern' objects}
1319106/773820   16.266    0.000  358.475    0.000 bitbake/lib/bb/data_smart.py:104(python_sub)
     4896   14.917    0.003  391.500    0.080 bitbake/lib/bb/data.py:374(generate_dependencies)
 14239267   13.084    0.000   18.379    0.000 /usr/lib64/python3.7/re.py:271(_compile)
 14136957   12.714    0.000  212.193    0.000 /usr/lib64/python3.7/fnmatch.py:38(_compile_pattern)
 12195278   11.936    0.000  187.820    0.000 /usr/lib64/python3.7/fnmatch.py:64(fnmatchcase)
  2065748   11.876    0.000   11.876    0.000 {built-in method _hashlib.openssl_sha256}
  1774895   11.398    0.000   32.347    0.000 bitbake/lib/bb/data_smart.py:482(setVar)
  1711440   10.938    0.000   14.160    0.000 bitbake/lib/bb/data_smart.py:567(_setvar_update_overrides)
6414398/3777277   10.435    0.000  328.932    0.000 bitbake/lib/bb/data_smart.py:92(var_sub)
 60719798   10.101    0.000   10.101    0.000 {method 'startswith' of 'str' objects}
 27097566    9.710    0.000    9.710    0.000 {method 'split' of 'str' objects}
  3476822    8.893    0.000   28.530    0.000 bitbake/lib/bb/data_smart.py:861(getVarFlags)
  1836339    8.289    0.000   18.643    0.000 bitbake/lib/bb/codeparser.py:284(parse_python)
  1836339    7.981    0.000   62.283    0.000 bitbake/lib/bb/codeparser.py:273(__init__)
 11265608    7.932    0.000   17.316    0.000 /usr/lib64/python3.7/copy.py:66(copy)
  2540267    7.258    0.000    7.258    0.000 {built-in method posix.lstat}

Re: [bitbake-devel] [PATCH] event: Fix multiconfig event handler change performance regressions

[Richard Purdie]

On Thu, 2021-03-11 at 22:14 +0000, Peter Kjellerstedt wrote:
> 
> While this greatly improves the situation, it is still not good. Here are some 
> numbers for me when parsing poky + openembedded + our layers:
> 
> poky + openembedded + axis dunfell
> Parsing recipes: 100% |###############################| Time: 0:00:39
> Parsing of 3935 .bb files complete (0 cached, 3935 parsed). 
> 5767 targets, 711 skipped, 0 masked, 0 errors.
> 
> poky + openembedded + axis gatesgarth
> Parsing recipes: 100% |###############################| Time: 0:00:39
> Parsing of 4051 .bb files complete (0 cached, 4051 parsed). 
> 5490 targets, 726 skipped, 0 masked, 0 errors.
> 
> poky + openembedded + axis master
> Parsing recipes: 100% |###############################| Time: 0:01:07
> Parsing of 4111 .bb files complete (0 cached, 4111 parsed). 
> 5607 targets, 732 skipped, 12 masked, 0 errors.
> 
> And here are similar measurements with only the poky and openembedded layers 
> (meta, meta-poky, meta-gplv2, meta-oe, meta-filesystems, meta-networking, 
> meta-python and meta-webserver):
> 
> poky + openembedded gatesgarth
> Parsing recipes: 100% |###############################| Time: 0:00:17
> Parsing of 2289 .bb files complete (0 cached, 2289 parsed). 
> 3537 targets, 91 skipped, 0 masked, 0 errors.
> 
> poky + openembedded master
> Parsing recipes: 100% |###############################| Time: 0:00:27
> Parsing of 2354 .bb files complete (0 cached, 2354 parsed). 
> 3659 targets, 64 skipped, 0 masked, 0 errors.
> 
> I have attached profiling logs (first 40 lines) for a gatesgarth run and a 
> master run. If I read the data correctly, it seems that during the master 
> parsing, there are a lot of calls to fnmatch.translate, posix.read and 
> _posixsubprocess.fork_exec that are not there during the gatesgarth parsing.

Was this with or without c3f6fee42bfa23f23f167cb29f0cfa05ac2fa197 from bitbake
master?

If with, please send those full profiles to me offlist. You're right about the
increased re.Pattern objects, there should be information further down about
where those calls came from too.

Cheers,

Richard

Re: [bitbake-devel] [PATCH] event: Fix multiconfig event handler change performance regressions

[Peter Kjellerstedt]

> -----Original Message-----
> From: Richard Purdie <richard.purdie@linuxfoundation.org>
> Sent: den 11 mars 2021 23:49
> To: Peter Kjellerstedt <peter.kjellerstedt@axis.com>; bitbake-
> devel@lists.openembedded.org
> Subject: Re: [bitbake-devel] [PATCH] event: Fix multiconfig event handler
> change performance regressions
> 
> On Thu, 2021-03-11 at 22:14 +0000, Peter Kjellerstedt wrote:
> >
> > While this greatly improves the situation, it is still not good. Here
> are some
> > numbers for me when parsing poky + openembedded + our layers:
> >
> > poky + openembedded + axis dunfell
> > Parsing recipes: 100% |###############################| Time: 0:00:39
> > Parsing of 3935 .bb files complete (0 cached, 3935 parsed).
> > 5767 targets, 711 skipped, 0 masked, 0 errors.
> >
> > poky + openembedded + axis gatesgarth
> > Parsing recipes: 100% |###############################| Time: 0:00:39
> > Parsing of 4051 .bb files complete (0 cached, 4051 parsed).
> > 5490 targets, 726 skipped, 0 masked, 0 errors.
> >
> > poky + openembedded + axis master
> > Parsing recipes: 100% |###############################| Time: 0:01:07
> > Parsing of 4111 .bb files complete (0 cached, 4111 parsed).
> > 5607 targets, 732 skipped, 12 masked, 0 errors.
> >
> > And here are similar measurements with only the poky and openembedded
> layers
> > (meta, meta-poky, meta-gplv2, meta-oe, meta-filesystems, meta-
> networking,
> > meta-python and meta-webserver):
> >
> > poky + openembedded gatesgarth
> > Parsing recipes: 100% |###############################| Time: 0:00:17
> > Parsing of 2289 .bb files complete (0 cached, 2289 parsed).
> > 3537 targets, 91 skipped, 0 masked, 0 errors.
> >
> > poky + openembedded master
> > Parsing recipes: 100% |###############################| Time: 0:00:27
> > Parsing of 2354 .bb files complete (0 cached, 2354 parsed).
> > 3659 targets, 64 skipped, 0 masked, 0 errors.
> >
> > I have attached profiling logs (first 40 lines) for a gatesgarth run and a
> > master run. If I read the data correctly, it seems that during the master
> > parsing, there are a lot of calls to fnmatch.translate, posix.read and
> > _posixsubprocess.fork_exec that are not there during the gatesgarth parsing.
> 
> Was this with or without c3f6fee42bfa23f23f167cb29f0cfa05ac2fa197 from bitbake
> master?

The time measurements were without it, but the profile log was with it. Adding 
it seems to shave off another 5 seconds when I parse all our layers.

> If with, please send those full profiles to me offlist. You're right about the
> increased re.Pattern objects, there should be information further down about
> where those calls came from too.

Will do. 

I also did some tracing of active processes while the parsing was running, and it 
seems the process that is forked during the master parsing is `git rev-parse HEAD`.

> Cheers,
> 
> Richard

//Peter

Re: [bitbake-devel] [PATCH] event: Fix multiconfig event handler change performance regressions

[Richard Purdie]

On Thu, 2021-03-11 at 23:04 +0000, Peter Kjellerstedt wrote:
> > -----Original Message-----
> > From: Richard Purdie <richard.purdie@linuxfoundation.org>
> > Sent: den 11 mars 2021 23:49
> > To: Peter Kjellerstedt <peter.kjellerstedt@axis.com>; bitbake-
> > devel@lists.openembedded.org
> > Subject: Re: [bitbake-devel] [PATCH] event: Fix multiconfig event handler
> > change performance regressions
> > 
> > On Thu, 2021-03-11 at 22:14 +0000, Peter Kjellerstedt wrote:
> > > 
> > > While this greatly improves the situation, it is still not good. Here
> > are some
> > > numbers for me when parsing poky + openembedded + our layers:
> > > 
> > > poky + openembedded + axis dunfell
> > > Parsing recipes: 100% |###############################| Time: 0:00:39
> > > Parsing of 3935 .bb files complete (0 cached, 3935 parsed).
> > > 5767 targets, 711 skipped, 0 masked, 0 errors.
> > > 
> > > poky + openembedded + axis gatesgarth
> > > Parsing recipes: 100% |###############################| Time: 0:00:39
> > > Parsing of 4051 .bb files complete (0 cached, 4051 parsed).
> > > 5490 targets, 726 skipped, 0 masked, 0 errors.
> > > 
> > > poky + openembedded + axis master
> > > Parsing recipes: 100% |###############################| Time: 0:01:07
> > > Parsing of 4111 .bb files complete (0 cached, 4111 parsed).
> > > 5607 targets, 732 skipped, 12 masked, 0 errors.
> > > 
> > > And here are similar measurements with only the poky and openembedded
> > layers
> > > (meta, meta-poky, meta-gplv2, meta-oe, meta-filesystems, meta-
> > networking,
> > > meta-python and meta-webserver):
> > > 
> > > poky + openembedded gatesgarth
> > > Parsing recipes: 100% |###############################| Time: 0:00:17
> > > Parsing of 2289 .bb files complete (0 cached, 2289 parsed).
> > > 3537 targets, 91 skipped, 0 masked, 0 errors.
> > > 
> > > poky + openembedded master
> > > Parsing recipes: 100% |###############################| Time: 0:00:27
> > > Parsing of 2354 .bb files complete (0 cached, 2354 parsed).
> > > 3659 targets, 64 skipped, 0 masked, 0 errors.
> > > 
> > > I have attached profiling logs (first 40 lines) for a gatesgarth run and a
> > > master run. If I read the data correctly, it seems that during the master
> > > parsing, there are a lot of calls to fnmatch.translate, posix.read and
> > > _posixsubprocess.fork_exec that are not there during the gatesgarth parsing.
> > 
> > Was this with or without c3f6fee42bfa23f23f167cb29f0cfa05ac2fa197 from bitbake
> > master?
> 
> The time measurements were without it, but the profile log was with it. Adding 
> it seems to shave off another 5 seconds when I parse all our layers.
> 
> > If with, please send those full profiles to me offlist. You're right about the
> > increased re.Pattern objects, there should be information further down about
> > where those calls came from too.
> 
> Will do. 
> 
> I also did some tracing of active processes while the parsing was running, and it 
> seems the process that is forked during the master parsing is `git rev-parse HEAD`.

Hmm, that makes me think of:

commit bd6b25f9a3416ce63e26d763cce7ed1ad4fd816d
Author: Alexander Kanavin <alex.kanavin@gmail.com>
Date:   Thu Dec 3 16:07:29 2020 +0100
poky.conf: do not write current date into distro version, use git hash instead

An immediate expansion of METADATA_REVISION may help.

Cheers,

Richard

Re: [bitbake-devel] [PATCH] event: Fix multiconfig event handler change performance regressions

[Peter Kjellerstedt]

> -----Original Message-----
> From: Richard Purdie <richard.purdie@linuxfoundation.org>
> Sent: den 12 mars 2021 00:13
> To: Peter Kjellerstedt <peter.kjellerstedt@axis.com>; bitbake-
> devel@lists.openembedded.org
> Subject: Re: [bitbake-devel] [PATCH] event: Fix multiconfig event handler
> change performance regressions
> 
> On Thu, 2021-03-11 at 23:04 +0000, Peter Kjellerstedt wrote:
> > > -----Original Message-----
> > > From: Richard Purdie <richard.purdie@linuxfoundation.org>
> > > Sent: den 11 mars 2021 23:49
> > > To: Peter Kjellerstedt <peter.kjellerstedt@axis.com>; bitbake-
> > > devel@lists.openembedded.org
> > > Subject: Re: [bitbake-devel] [PATCH] event: Fix multiconfig event
> handler
> > > change performance regressions
> > >
> > > On Thu, 2021-03-11 at 22:14 +0000, Peter Kjellerstedt wrote:
> > > >
> > > > While this greatly improves the situation, it is still not good.
> Here
> > > are some
> > > > numbers for me when parsing poky + openembedded + our layers:
> > > >
> > > > poky + openembedded + axis dunfell
> > > > Parsing recipes: 100% |###############################| Time:
> 0:00:39
> > > > Parsing of 3935 .bb files complete (0 cached, 3935 parsed).
> > > > 5767 targets, 711 skipped, 0 masked, 0 errors.
> > > >
> > > > poky + openembedded + axis gatesgarth
> > > > Parsing recipes: 100% |###############################| Time:
> 0:00:39
> > > > Parsing of 4051 .bb files complete (0 cached, 4051 parsed).
> > > > 5490 targets, 726 skipped, 0 masked, 0 errors.
> > > >
> > > > poky + openembedded + axis master
> > > > Parsing recipes: 100% |###############################| Time:
> 0:01:07
> > > > Parsing of 4111 .bb files complete (0 cached, 4111 parsed).
> > > > 5607 targets, 732 skipped, 12 masked, 0 errors.
> > > >
> > > > And here are similar measurements with only the poky and
> openembedded
> > > layers
> > > > (meta, meta-poky, meta-gplv2, meta-oe, meta-filesystems, meta-
> > > networking,
> > > > meta-python and meta-webserver):
> > > >
> > > > poky + openembedded gatesgarth
> > > > Parsing recipes: 100% |###############################| Time:
> 0:00:17
> > > > Parsing of 2289 .bb files complete (0 cached, 2289 parsed).
> > > > 3537 targets, 91 skipped, 0 masked, 0 errors.
> > > >
> > > > poky + openembedded master
> > > > Parsing recipes: 100% |###############################| Time:
> 0:00:27
> > > > Parsing of 2354 .bb files complete (0 cached, 2354 parsed).
> > > > 3659 targets, 64 skipped, 0 masked, 0 errors.
> > > >
> > > > I have attached profiling logs (first 40 lines) for a gatesgarth run
> and a
> > > > master run. If I read the data correctly, it seems that during the
> master
> > > > parsing, there are a lot of calls to fnmatch.translate, posix.read
> and
> > > > _posixsubprocess.fork_exec that are not there during the gatesgarth
> parsing.
> > >
> > > Was this with or without c3f6fee42bfa23f23f167cb29f0cfa05ac2fa197 from
> bitbake
> > > master?
> >
> > The time measurements were without it, but the profile log was with it.
> Adding
> > it seems to shave off another 5 seconds when I parse all our layers.
> >
> > > If with, please send those full profiles to me offlist. You're right
> about the
> > > increased re.Pattern objects, there should be information further down
> about
> > > where those calls came from too.
> >
> > Will do.
> >
> > I also did some tracing of active processes while the parsing was
> running, and it
> > seems the process that is forked during the master parsing is `git rev-
> parse HEAD`.
> 
> Hmm, that makes me think of:
> 
> commit bd6b25f9a3416ce63e26d763cce7ed1ad4fd816d
> Author: Alexander Kanavin <alex.kanavin@gmail.com>
> Date:   Thu Dec 3 16:07:29 2020 +0100
> poky.conf: do not write current date into distro version, use git hash
> instead
> 
> An immediate expansion of METADATA_REVISION may help.
> 
> Cheers,
> 
> Richard

Changing metadata_scm.bbclass so that METADATA_REVISION (and METADATA_BRANCH) 
are defined using := instead of ?= does get rid of the fork_exec calls. But 
unfortunately it does not seem to affect the parsing time.

//Peter

Re: [bitbake-devel] [PATCH] event: Fix multiconfig event handler change performance regressions

[Peter Kjellerstedt]

> -----Original Message-----
> From: bitbake-devel@lists.openembedded.org <bitbake-
> devel@lists.openembedded.org> On Behalf Of Peter Kjellerstedt
> Sent: den 12 mars 2021 01:43
> To: Richard Purdie <richard.purdie@linuxfoundation.org>; bitbake-
> devel@lists.openembedded.org
> Subject: Re: [bitbake-devel] [PATCH] event: Fix multiconfig event handler
> change performance regressions
> 
> > -----Original Message-----
> > From: Richard Purdie <richard.purdie@linuxfoundation.org>
> > Sent: den 12 mars 2021 00:13
> > To: Peter Kjellerstedt <peter.kjellerstedt@axis.com>; bitbake-
> > devel@lists.openembedded.org
> > Subject: Re: [bitbake-devel] [PATCH] event: Fix multiconfig event
> handler
> > change performance regressions
> >
> > On Thu, 2021-03-11 at 23:04 +0000, Peter Kjellerstedt wrote:
> > > > -----Original Message-----
> > > > From: Richard Purdie <richard.purdie@linuxfoundation.org>
> > > > Sent: den 11 mars 2021 23:49
> > > > To: Peter Kjellerstedt <peter.kjellerstedt@axis.com>; bitbake-
> > > > devel@lists.openembedded.org
> > > > Subject: Re: [bitbake-devel] [PATCH] event: Fix multiconfig event
> > handler
> > > > change performance regressions
> > > >
> > > > On Thu, 2021-03-11 at 22:14 +0000, Peter Kjellerstedt wrote:
> > > > >
> > > > > While this greatly improves the situation, it is still not good.
> > Here
> > > > are some
> > > > > numbers for me when parsing poky + openembedded + our layers:
> > > > >
> > > > > poky + openembedded + axis dunfell
> > > > > Parsing recipes: 100% |###############################| Time:
> > 0:00:39
> > > > > Parsing of 3935 .bb files complete (0 cached, 3935 parsed).
> > > > > 5767 targets, 711 skipped, 0 masked, 0 errors.
> > > > >
> > > > > poky + openembedded + axis gatesgarth
> > > > > Parsing recipes: 100% |###############################| Time:
> > 0:00:39
> > > > > Parsing of 4051 .bb files complete (0 cached, 4051 parsed).
> > > > > 5490 targets, 726 skipped, 0 masked, 0 errors.
> > > > >
> > > > > poky + openembedded + axis master
> > > > > Parsing recipes: 100% |###############################| Time:
> > 0:01:07
> > > > > Parsing of 4111 .bb files complete (0 cached, 4111 parsed).
> > > > > 5607 targets, 732 skipped, 12 masked, 0 errors.
> > > > >
> > > > > And here are similar measurements with only the poky and
> > openembedded
> > > > layers
> > > > > (meta, meta-poky, meta-gplv2, meta-oe, meta-filesystems, meta-
> > > > networking,
> > > > > meta-python and meta-webserver):
> > > > >
> > > > > poky + openembedded gatesgarth
> > > > > Parsing recipes: 100% |###############################| Time:
> > 0:00:17
> > > > > Parsing of 2289 .bb files complete (0 cached, 2289 parsed).
> > > > > 3537 targets, 91 skipped, 0 masked, 0 errors.
> > > > >
> > > > > poky + openembedded master
> > > > > Parsing recipes: 100% |###############################| Time:
> > 0:00:27
> > > > > Parsing of 2354 .bb files complete (0 cached, 2354 parsed).
> > > > > 3659 targets, 64 skipped, 0 masked, 0 errors.
> > > > >
> > > > > I have attached profiling logs (first 40 lines) for a gatesgarth
> run
> > and a
> > > > > master run. If I read the data correctly, it seems that during the
> > master
> > > > > parsing, there are a lot of calls to fnmatch.translate, posix.read
> > and
> > > > > _posixsubprocess.fork_exec that are not there during the
> gatesgarth
> > parsing.
> > > >
> > > > Was this with or without c3f6fee42bfa23f23f167cb29f0cfa05ac2fa197
> from
> > bitbake
> > > > master?
> > >
> > > The time measurements were without it, but the profile log was with
> it.
> > Adding
> > > it seems to shave off another 5 seconds when I parse all our layers.
> > >
> > > > If with, please send those full profiles to me offlist. You're right
> > about the
> > > > increased re.Pattern objects, there should be information further
> down
> > about
> > > > where those calls came from too.
> > >
> > > Will do.
> > >
> > > I also did some tracing of active processes while the parsing was
> > running, and it
> > > seems the process that is forked during the master parsing is `git
> rev-
> > parse HEAD`.
> >
> > Hmm, that makes me think of:
> >
> > commit bd6b25f9a3416ce63e26d763cce7ed1ad4fd816d
> > Author: Alexander Kanavin <alex.kanavin@gmail.com>
> > Date:   Thu Dec 3 16:07:29 2020 +0100
> > poky.conf: do not write current date into distro version, use git hash
> > instead
> >
> > An immediate expansion of METADATA_REVISION may help.
> >
> > Cheers,
> >
> > Richard
> 
> Changing metadata_scm.bbclass so that METADATA_REVISION (and
> METADATA_BRANCH)
> are defined using := instead of ?= does get rid of the fork_exec calls.
> But unfortunately it does not seem to affect the parsing time.

Actually, it does. With immediate expansion of METADATA_REVISION and the 
c3f6fee42 commit, the parsing time for poky + openembedded are back to the 
same as with gatesgarth.

I had a further look at the profiling data, and I figured out the cause of 
the rest of the increased parsing time. It is this commit that causes it:

commit 08cbf17485b6443a6118acfac8200eb6c61445a3
Author: Richard Purdie <richard.purdie@linuxfoundation.org>
Date:   Thu Feb 18 15:07:11 2021 +0000
licenses: Update INCOMPATIBLE_LICENSE for 'or-later' handling

It does not affect the parsing time with only the poky and openembedded 
layers, but when we add our layers that has an INCOMPATIBLE_LICENSE that 
contains 190 licenses, the effect is significant.

However, what I don't understand is why that change has such a 
significant effect. Because spontaneously it looks as it should only 
approximately double the number of incompatible licenses (in our case 
from 190 to 374), but if I remove it (so I am back to the parsing time 
with Gatesgarth), and then also drop almost all licenses from our 
INCOMPATIBLE_LICENSE (only keeping the GPL3 ones), the parsing time is 
only further improved by about two seconds.

That said, I now have a patch that avoids the problem by only adding 
"foo+" to the list of incompatible licenses if "foo+" exists in 
SPDXLICENSEMAP. That way the list doesn't increase at all for us 
(we already use the "foo-only" and "foo-or-later" licenses in 
INCOMPATIBLE_LICENSE), and it won't contain nonsense "foo+" licenses 
for others. I will send that patch along shortly.

I will also send the patch to define METADATA_REVISION using immediate 
expansion.

> //Peter

//Peter