[PATCH yocto-autobuilder-helper 1/4] config.json: add "collect-data" template

[PATCH yocto-autobuilder-helper 1/4] config.json: add "collect-data" template

[sakib.sajal]

collect-data template can run arbitrary commands/scripts
on a regular basis and logs the output in a file.

See oe-core for more details:
    edb7098e9e buildstats.bbclass: add functionality to collect build system stats

Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
---
 config.json | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/config.json b/config.json
index 5bfa240..c43d231 100644
--- a/config.json
+++ b/config.json
@@ -87,6 +87,13 @@
                 "SANITYTARGETS" : "core-image-full-cmdline:do_testimage core-image-sato:do_testimage core-image-sato-sdk:do_testimage"
             }
         },
+	"collect-data" : {
+            "extravars" : [
+                "BB_HEARTBEAT_EVENT = '10'",
+                "BB_LOG_HOST_STAT_ON_INTERVAL = '1'",
+                "BB_LOG_HOST_STAT_CMDS = 'oe-time-dd-test.sh 100'"
+            ]
+        },
         "ptest-qemu" : {
             "BUILDINFO" : true,
             "BBTARGETS" : "core-image-sato-ptest",
-- 
2.25.1

[PATCH yocto-autobuilder-helper 2/4] config.json: collect data by default

[sakib.sajal]

add the variables required to collect data to "defaults"
so that data is collected on all builds.

Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
---
 config.json | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/config.json b/config.json
index c43d231..cd82047 100644
--- a/config.json
+++ b/config.json
@@ -55,7 +55,10 @@
             "SDK_INCLUDE_TOOLCHAIN = '1'",
             "BB_DISKMON_DIRS = 'STOPTASKS,${TMPDIR},1G,100K STOPTASKS,${DL_DIR},1G STOPTASKS,${SSTATE_DIR},1G STOPTASKS,/tmp,100M,100K ABORT,${TMPDIR},100M,1K ABORT,${DL_DIR},100M ABORT,${SSTATE_DIR},100M ABORT,/tmp,10M,1K'",
             "BB_HASHSERVE = 'typhoon.yocto.io:8686'",
-            "RUNQEMU_TMPFS_DIR = '/home/pokybuild/tmp'"
+            "RUNQEMU_TMPFS_DIR = '/home/pokybuild/tmp'",
+            "BB_HEARTBEAT_EVENT = '10'",
+            "BB_LOG_HOST_STAT_ON_INTERVAL = '1'",
+            "BB_LOG_HOST_STAT_CMDS = 'oe-time-dd-test.sh 100'"
         ]
     },
     "templates" : {
-- 
2.25.1

Re: [yocto] [PATCH yocto-autobuilder-helper 2/4] config.json: collect data by default

[Richard Purdie]

On Tue, 2021-04-13 at 13:02 -0400, sakib.sajal@windriver.com wrote:
> add the variables required to collect data to "defaults"
> so that data is collected on all builds.
> 
> Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
> Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
> ---
>  config.json | 5 ++++-
>  1 file changed, 4 insertions(+), 1 deletion(-)
> 
> diff --git a/config.json b/config.json
> index c43d231..cd82047 100644
> --- a/config.json
> +++ b/config.json
> @@ -55,7 +55,10 @@
>              "SDK_INCLUDE_TOOLCHAIN = '1'",
>              "BB_DISKMON_DIRS = 'STOPTASKS,${TMPDIR},1G,100K STOPTASKS,${DL_DIR},1G STOPTASKS,${SSTATE_DIR},1G STOPTASKS,/tmp,100M,100K ABORT,${TMPDIR},100M,1K ABORT,${DL_DIR},100M ABORT,${SSTATE_DIR},100M ABORT,/tmp,10M,1K'",
>              "BB_HASHSERVE = 'typhoon.yocto.io:8686'",
> -            "RUNQEMU_TMPFS_DIR = '/home/pokybuild/tmp'"
> +            "RUNQEMU_TMPFS_DIR = '/home/pokybuild/tmp'",
> +            "BB_HEARTBEAT_EVENT = '10'",
> +            "BB_LOG_HOST_STAT_ON_INTERVAL = '1'",
> +            "BB_LOG_HOST_STAT_CMDS = 'oe-time-dd-test.sh 100'"
>          ]
>      },
>      "templates" : {

I merged 2-4 of this series, unfortunately this resulted in a few issues overnight:

https://autobuilder.yoctoproject.org/typhoon/#/builders/85/builds/1393

which is due to the non-executable script which there is a patch for, it just
wasn't in master due to the release. I've fixed that by merging the patches.

The bigger issue is the performance metrics which this broke:

https://autobuilder.yoctoproject.org/typhoon/#/builders/91/builds/4427
https://autobuilder.yoctoproject.org/typhoon/#/builders/92/builds/4453

We're going to need to disable these events on the performance metrics
targets...

Cheers,

Richard

Re: [yocto] [PATCH yocto-autobuilder-helper 2/4] config.json: collect data by default

[Richard Purdie]

On Fri, 2021-04-16 at 09:28 +0100, Richard Purdie via lists.yoctoproject.org wrote:
> On Tue, 2021-04-13 at 13:02 -0400, sakib.sajal@windriver.com wrote:
> > add the variables required to collect data to "defaults"
> > so that data is collected on all builds.
> > 
> > Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
> > Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
> > ---
> >  config.json | 5 ++++-
> >  1 file changed, 4 insertions(+), 1 deletion(-)
> > 
> > diff --git a/config.json b/config.json
> > index c43d231..cd82047 100644
> > --- a/config.json
> > +++ b/config.json
> > @@ -55,7 +55,10 @@
> >              "SDK_INCLUDE_TOOLCHAIN = '1'",
> >              "BB_DISKMON_DIRS = 'STOPTASKS,${TMPDIR},1G,100K STOPTASKS,${DL_DIR},1G STOPTASKS,${SSTATE_DIR},1G STOPTASKS,/tmp,100M,100K ABORT,${TMPDIR},100M,1K ABORT,${DL_DIR},100M ABORT,${SSTATE_DIR},100M ABORT,/tmp,10M,1K'",
> >              "BB_HASHSERVE = 'typhoon.yocto.io:8686'",
> > -            "RUNQEMU_TMPFS_DIR = '/home/pokybuild/tmp'"
> > +            "RUNQEMU_TMPFS_DIR = '/home/pokybuild/tmp'",
> > +            "BB_HEARTBEAT_EVENT = '10'",
> > +            "BB_LOG_HOST_STAT_ON_INTERVAL = '1'",
> > +            "BB_LOG_HOST_STAT_CMDS = 'oe-time-dd-test.sh 100'"
> >          ]
> >      },
> >      "templates" : {
> 
> I merged 2-4 of this series, unfortunately this resulted in a few issues overnight:
> 
> https://autobuilder.yoctoproject.org/typhoon/#/builders/85/builds/1393
> 
> which is due to the non-executable script which there is a patch for, it just
> wasn't in master due to the release. I've fixed that by merging the patches.
> 
> The bigger issue is the performance metrics which this broke:
> 
> https://autobuilder.yoctoproject.org/typhoon/#/builders/91/builds/4427
> https://autobuilder.yoctoproject.org/typhoon/#/builders/92/builds/4453
> 
> We're going to need to disable these events on the performance metrics
> targets...

There is also another issue as BB_HEARTBEAT_EVENT defaults to 1, the change to 10 
changes the default timings for buildstats and other pieces of code. In particular
I suspect this is breaking:

https://autobuilder.yoctoproject.org/typhoon/#/builders/80/builds/1993

and again in:

https://autobuilder.yoctoproject.org/typhoon/#/builders/79/builds/2014

in the disk monitoring selftest...

Cheers,

Richard

[PATCH yocto-autobuilder-helper 3/4] collect-results: collect "host_stats" files generated by collect-data template

[sakib.sajal]

collect-data template generates host_stats files which are collected.
All files are published, file names are determined by the contents:
    - Files that contain "top" output are named host_stats_<number>_top.txt
    - host_stats_<number>.txt otherwise

Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
---
 scripts/collect-results | 19 +++++++++++++++++++
 1 file changed, 19 insertions(+)

diff --git a/scripts/collect-results b/scripts/collect-results
index 5db43fb..7474e36 100755
--- a/scripts/collect-results
+++ b/scripts/collect-results
@@ -17,3 +17,22 @@ if [ -e $WORKDIR/buildhistory ]; then
         $WORKDIR/../scripts/buildhistory-diff -p $WORKDIR/buildhistory ab-fetchrev > $DEST/$target/buildhistory.txt
     fi
 fi
+
+HSFILE=$WORKDIR/tmp/buildstats/*/host_stats
+d=`date +%Y-%m-%d--%H-%M`
+
+mkdir -p $DEST/$target/$d
+
+step=0
+for f in $HSFILE; do
+	if [ -e $f ]; then
+	    cp $f $DEST/$target/$d
+	    grep -m 1 "^top -" $f
+	    if [ $? -eq 0 ]; then
+		    mv $DEST/$target/$d/`basename $f` $DEST/$target/$d/`basename $f`_${step}_top.txt
+	    else
+		    mv $DEST/$target/$d/`basename $f` $DEST/$target/$d/`basename $f`_${step}.txt
+	    fi
+	    step=$((step+1))
+	fi
+done
-- 
2.25.1

[PATCH yocto-autobuilder-helper 4/4] generate-testresult-index.py: publish host data collected by collect-data template

[sakib.sajal]

Add a column "Host Data" to publish the host data collected.

Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
---
 scripts/generate-testresult-index.py | 18 +++++++++++++++++-
 1 file changed, 17 insertions(+), 1 deletion(-)

diff --git a/scripts/generate-testresult-index.py b/scripts/generate-testresult-index.py
index d9d577e..7fdc17c 100755
--- a/scripts/generate-testresult-index.py
+++ b/scripts/generate-testresult-index.py
@@ -33,6 +33,7 @@ index_templpate = """
   <th>Performance Reports</th>
   <th>ptest Logs</th>
   <th>Buildhistory</th>
+  <th>Host Data</th>
 </tr>
 </thead>
 <tdata>
@@ -57,6 +58,11 @@ index_templpate = """
      <a href="{{bh[0]}}">{{bh[1]}}</a>
    {% endfor %}
    </td>
+   <td>
+   {% for hd in entry[8] %}
+     <a href="{{hd[0]}}">{{hd[1]}}</a>
+   {% endfor %}
+   </td>
 </tr>
 {% endfor %}
 </tdata>
@@ -145,9 +151,19 @@ for build in sorted(os.listdir(path), key=keygen, reverse=True):
     if os.path.exists(buildpath + "/qemuarm/buildhistory.txt"):
         buildhistory.append((reldir + "testresults/qemuarm/buildhistory.txt", "qemuarm"))
 
+    hd = []
+    counter = 0
+    # do we really need the loop?
+    for p in glob.glob(buildpath + "/*/*/host_stats*top.txt"):
+        n_split = p.split(build)
+        res = reldir[0:-1] + n_split[1]
+        hd.append((res, str(counter)))
+        counter += 1
+
+
     branch = get_build_branch(buildpath)
 
-    entries.append((build, reldir, btype, testreport, branch, buildhistory, perfreports, ptestlogs))
+    entries.append((build, reldir, btype, testreport, branch, buildhistory, perfreports, ptestlogs, hd))
 
     # Also ensure we have saved out log data for ptest runs to aid debugging
     if "ptest" in btype or btype in ["full", "quick"]:
-- 
2.25.1

Re: [yocto] [PATCH yocto-autobuilder-helper 1/4] config.json: add "collect-data" template

[Richard Purdie]

On Tue, 2021-04-13 at 13:02 -0400, sakib.sajal@windriver.com wrote:
> collect-data template can run arbitrary commands/scripts
> on a regular basis and logs the output in a file.
> 
> See oe-core for more details:
>     edb7098e9e buildstats.bbclass: add functionality to collect build system stats
> 
> Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
> Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
> ---
>  config.json | 7 +++++++
>  1 file changed, 7 insertions(+)
> 
> diff --git a/config.json b/config.json
> index 5bfa240..c43d231 100644
> --- a/config.json
> +++ b/config.json
> @@ -87,6 +87,13 @@
>                  "SANITYTARGETS" : "core-image-full-cmdline:do_testimage core-image-sato:do_testimage core-image-sato-sdk:do_testimage"
>              }
>          },
> +	"collect-data" : {
> +            "extravars" : [
> +                "BB_HEARTBEAT_EVENT = '10'",
> +                "BB_LOG_HOST_STAT_ON_INTERVAL = '1'",
> +                "BB_LOG_HOST_STAT_CMDS = 'oe-time-dd-test.sh 100'"
> +            ]
> +        },

Is the template used anywhere? I can't remember if we support nesting templates in which 
case this is useful, or not?

Cheers,

Richard

Re: [yocto] [PATCH yocto-autobuilder-helper 1/4] config.json: add "collect-data" template

[sakib.sajal]

On 2021-04-15 9:52 a.m., Richard Purdie wrote:
> [Please note: This e-mail is from an EXTERNAL e-mail address]
>
> On Tue, 2021-04-13 at 13:02 -0400, sakib.sajal@windriver.com wrote:
>> collect-data template can run arbitrary commands/scripts
>> on a regular basis and logs the output in a file.
>>
>> See oe-core for more details:
>>      edb7098e9e buildstats.bbclass: add functionality to collect build system stats
>>
>> Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
>> Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
>> ---
>>   config.json | 7 +++++++
>>   1 file changed, 7 insertions(+)
>>
>> diff --git a/config.json b/config.json
>> index 5bfa240..c43d231 100644
>> --- a/config.json
>> +++ b/config.json
>> @@ -87,6 +87,13 @@
>>                   "SANITYTARGETS" : "core-image-full-cmdline:do_testimage core-image-sato:do_testimage core-image-sato-sdk:do_testimage"
>>               }
>>           },
>> +     "collect-data" : {
>> +            "extravars" : [
>> +                "BB_HEARTBEAT_EVENT = '10'",
>> +                "BB_LOG_HOST_STAT_ON_INTERVAL = '1'",
>> +                "BB_LOG_HOST_STAT_CMDS = 'oe-time-dd-test.sh 100'"
>> +            ]
>> +        },
> Is the template used anywhere? I can't remember if we support nesting templates in which
> case this is useful, or not?
>
> Cheers,
>
> Richard

The template is not used anywhere, yet, the initial patchset enables the 
data collection by default.

I have left the template in case the data collection is removed from 
defaults and need to be used on a case by case basis.

I am not entirely sure if nesting templates work. I have not seen any 
examples of it, neither did i try it myself. If nesting does work, the 
template should be useful.

Sakib

>

Re: [yocto] [PATCH yocto-autobuilder-helper 1/4] config.json: add "collect-data" template

[Richard Purdie]

On Thu, 2021-04-15 at 11:31 -0400, Sakib Sajal wrote:
> On 2021-04-15 9:52 a.m., Richard Purdie wrote:
> > [Please note: This e-mail is from an EXTERNAL e-mail address]
> > 
> > On Tue, 2021-04-13 at 13:02 -0400, sakib.sajal@windriver.com wrote:
> > > collect-data template can run arbitrary commands/scripts
> > > on a regular basis and logs the output in a file.
> > > 
> > > See oe-core for more details:
> > >      edb7098e9e buildstats.bbclass: add functionality to collect build system stats
> > > 
> > > Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
> > > Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
> > > ---
> > >   config.json | 7 +++++++
> > >   1 file changed, 7 insertions(+)
> > > 
> > > diff --git a/config.json b/config.json
> > > index 5bfa240..c43d231 100644
> > > --- a/config.json
> > > +++ b/config.json
> > > @@ -87,6 +87,13 @@
> > >                   "SANITYTARGETS" : "core-image-full-cmdline:do_testimage core-image-sato:do_testimage core-image-sato-sdk:do_testimage"
> > >               }
> > >           },
> > > +     "collect-data" : {
> > > +            "extravars" : [
> > > +                "BB_HEARTBEAT_EVENT = '10'",
> > > +                "BB_LOG_HOST_STAT_ON_INTERVAL = '1'",
> > > +                "BB_LOG_HOST_STAT_CMDS = 'oe-time-dd-test.sh 100'"
> > > +            ]
> > > +        },
> > Is the template used anywhere? I can't remember if we support nesting templates in which
> > case this is useful, or not?
> > 
> > Cheers,
> > 
> > Richard
> 
> The template is not used anywhere, yet, the initial patchset enables the 
> data collection by default.
> 
> I have left the template in case the data collection is removed from 
> defaults and need to be used on a case by case basis.
> 
> I am not entirely sure if nesting templates work. I have not seen any 
> examples of it, neither did i try it myself. If nesting does work, the 
> template should be useful.

I had a quick look at the code and sadly, it doesn't appear I implemented 
nesting so this wouldn't be that useful as things stand.

Cheers,

Richard

Re: [yocto] [PATCH yocto-autobuilder-helper 1/4] config.json: add "collect-data" template

[Randy MacLeod]

On 2021-04-15 11:55 a.m., Richard Purdie wrote:
> On Thu, 2021-04-15 at 11:31 -0400, Sakib Sajal wrote:
>> On 2021-04-15 9:52 a.m., Richard Purdie wrote:
>>> [Please note: This e-mail is from an EXTERNAL e-mail address]
>>>
>>> On Tue, 2021-04-13 at 13:02 -0400, sakib.sajal@windriver.com wrote:
>>>> collect-data template can run arbitrary commands/scripts
>>>> on a regular basis and logs the output in a file.
>>>>
>>>> See oe-core for more details:
>>>>       edb7098e9e buildstats.bbclass: add functionality to collect build system stats
>>>>
>>>> Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
>>>> Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
>>>> ---
>>>>    config.json | 7 +++++++
>>>>    1 file changed, 7 insertions(+)
>>>>
>>>> diff --git a/config.json b/config.json
>>>> index 5bfa240..c43d231 100644
>>>> --- a/config.json
>>>> +++ b/config.json
>>>> @@ -87,6 +87,13 @@
>>>>                    "SANITYTARGETS" : "core-image-full-cmdline:do_testimage core-image-sato:do_testimage core-image-sato-sdk:do_testimage"
>>>>                }
>>>>            },
>>>> +     "collect-data" : {
>>>> +            "extravars" : [
>>>> +                "BB_HEARTBEAT_EVENT = '10'",
>>>> +                "BB_LOG_HOST_STAT_ON_INTERVAL = '1'",
>>>> +                "BB_LOG_HOST_STAT_CMDS = 'oe-time-dd-test.sh 100'"
>>>> +            ]
>>>> +        },
>>> Is the template used anywhere? I can't remember if we support nesting templates in which
>>> case this is useful, or not?

We were using it for testing on the YP AB and thought it would be
useful if at some point the monitoring was dropped from the
default config.

I think we can just add it later if needed.

../Randy
>>>
>>> Cheers,
>>>
>>> Richard
>>
>> The template is not used anywhere, yet, the initial patchset enables the
>> data collection by default.
>>
>> I have left the template in case the data collection is removed from
>> defaults and need to be used on a case by case basis.
>>
>> I am not entirely sure if nesting templates work. I have not seen any
>> examples of it, neither did i try it myself. If nesting does work, the
>> template should be useful.
> 
> I had a quick look at the code and sadly, it doesn't appear I implemented
> nesting so this wouldn't be that useful as things stand.
> 
> Cheers,
> 
> Richard
> 
> 
> 
> 
> 
> 


-- 
# Randy MacLeod
# Wind River Linux

Re: [yocto] [PATCH yocto-autobuilder-helper 1/4] config.json: add "collect-data" template

[Randy MacLeod]

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

On 2021-04-15 1:55 p.m., Randy MacLeod wrote:
> On 2021-04-15 11:55 a.m., Richard Purdie wrote:
>> On Thu, 2021-04-15 at 11:31 -0400, Sakib Sajal wrote:
>>> On 2021-04-15 9:52 a.m., Richard Purdie wrote:
>>>> [Please note: This e-mail is from an EXTERNAL e-mail address]
>>>>
>>>> On Tue, 2021-04-13 at 13:02 -0400, sakib.sajal@windriver.com wrote:
>>>>> collect-data template can run arbitrary commands/scripts
>>>>> on a regular basis and logs the output in a file.
>>>>>
>>>>> See oe-core for more details:
>>>>>       edb7098e9e buildstats.bbclass: add functionality to collect 
>>>>> build system stats
>>>>>
>>>>> Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
>>>>> Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
>>>>> ---
>>>>>    config.json | 7 +++++++
>>>>>    1 file changed, 7 insertions(+)
>>>>>
>>>>> diff --git a/config.json b/config.json
>>>>> index 5bfa240..c43d231 100644
>>>>> --- a/config.json
>>>>> +++ b/config.json
>>>>> @@ -87,6 +87,13 @@
>>>>>                    "SANITYTARGETS" : 
>>>>> "core-image-full-cmdline:do_testimage core-image-sato:do_testimage 
>>>>> core-image-sato-sdk:do_testimage"
>>>>>                }
>>>>>            },
>>>>> +     "collect-data" : {
>>>>> +            "extravars" : [
>>>>> +                "BB_HEARTBEAT_EVENT = '10'",
>>>>> +                "BB_LOG_HOST_STAT_ON_INTERVAL = '1'",
>>>>> +                "BB_LOG_HOST_STAT_CMDS = 'oe-time-dd-test.sh 100'"
>>>>> +            ]
>>>>> +        },
>>>> Is the template used anywhere? I can't remember if we support 
>>>> nesting templates in which
>>>> case this is useful, or not?
> 
> We were using it for testing on the YP AB and thought it would be
> useful if at some point the monitoring was dropped from the
> default config.
> 
> I think we can just add it later if needed.

Richard,

I think that the web server for:
   https://autobuilder.yocto.io/pub/non-release/
runs every 30 seconds via cron so if you are happy with
this crude dd trigger once things have soaked in master-next
and we want to gather some data overnight, could you merge to master?


I ran a simpler test with fewer io stressors from:
$ stress -hdd N
and have attached a graph with up to 3000! stressors that
we looked at this morning and another with up to 35 stressors.

It's a crude indicators but once we get beyond 18-20 io stressors
on the system I tested (48 cores, 128 GB RAM, 12 TB magnetic disk)
dd time become erratic.

Running qemu from tmpfs has clearly helped.
Let's gather some data and decide if we want to spend more time
learning how to monitor the system to tune how we are using it.

../Randy

> 
> ../Randy
>>>>
>>>> Cheers,
>>>>
>>>> Richard
>>>
>>> The template is not used anywhere, yet, the initial patchset enables the
>>> data collection by default.
>>>
>>> I have left the template in case the data collection is removed from
>>> defaults and need to be used on a case by case basis.
>>>
>>> I am not entirely sure if nesting templates work. I have not seen any
>>> examples of it, neither did i try it myself. If nesting does work, the
>>> template should be useful.
>>
>> I had a quick look at the code and sadly, it doesn't appear I implemented
>> nesting so this wouldn't be that useful as things stand.
>>
>> Cheers,
>>
>> Richard
>>
>>
>>
>>
>> 
>>
> 
> 


-- 
# Randy MacLeod
# Wind River Linux

[-- Attachment #2: stress-dd-80.png --]
[-- Type: image/png, Size: 8944 bytes --]

[-- Attachment #3: stress-dd-3000.png --]
[-- Type: image/png, Size: 16357 bytes --]

[-- Attachment #4: stress-dd-35.png --]
[-- Type: image/png, Size: 9760 bytes --]

Re: [yocto] [PATCH yocto-autobuilder-helper 1/4] config.json: add "collect-data" template

[Randy MacLeod]

On 2021-04-15 4:48 p.m., Randy MacLeod wrote:
> On 2021-04-15 1:55 p.m., Randy MacLeod wrote:
>> On 2021-04-15 11:55 a.m., Richard Purdie wrote:
>>> On Thu, 2021-04-15 at 11:31 -0400, Sakib Sajal wrote:
>>>> On 2021-04-15 9:52 a.m., Richard Purdie wrote:
>>>>> [Please note: This e-mail is from an EXTERNAL e-mail address]
>>>>>
>>>>> On Tue, 2021-04-13 at 13:02 -0400, sakib.sajal@windriver.com wrote:
>>>>>> collect-data template can run arbitrary commands/scripts
>>>>>> on a regular basis and logs the output in a file.
>>>>>>
>>>>>> See oe-core for more details:
>>>>>>       edb7098e9e buildstats.bbclass: add functionality to collect 
>>>>>> build system stats
>>>>>>
>>>>>> Signed-off-by: Sakib Sajal <sakib.sajal@windriver.com>
>>>>>> Signed-off-by: Randy MacLeod <Randy.MacLeod@windriver.com>
>>>>>> ---
>>>>>>    config.json | 7 +++++++
>>>>>>    1 file changed, 7 insertions(+)
>>>>>>
>>>>>> diff --git a/config.json b/config.json
>>>>>> index 5bfa240..c43d231 100644
>>>>>> --- a/config.json
>>>>>> +++ b/config.json
>>>>>> @@ -87,6 +87,13 @@
>>>>>>                    "SANITYTARGETS" : 
>>>>>> "core-image-full-cmdline:do_testimage 
>>>>>> core-image-sato:do_testimage core-image-sato-sdk:do_testimage"
>>>>>>                }
>>>>>>            },
>>>>>> +     "collect-data" : {
>>>>>> +            "extravars" : [
>>>>>> +                "BB_HEARTBEAT_EVENT = '10'",
>>>>>> +                "BB_LOG_HOST_STAT_ON_INTERVAL = '1'",
>>>>>> +                "BB_LOG_HOST_STAT_CMDS = 'oe-time-dd-test.sh 100'"
>>>>>> +            ]
>>>>>> +        },
>>>>> Is the template used anywhere? I can't remember if we support 
>>>>> nesting templates in which
>>>>> case this is useful, or not?
>>
>> We were using it for testing on the YP AB and thought it would be
>> useful if at some point the monitoring was dropped from the
>> default config.
>>
>> I think we can just add it later if needed.
>
> Richard,
>
> I think that the web server for:
>   https://autobuilder.yocto.io/pub/non-release/
> runs every 30 seconds via cron so if you are happy with
> this crude dd trigger once things have soaked in master-next
> and we want to gather some data overnight, could you merge to master?
>
>
> I ran a simpler test with fewer io stressors from:
> $ stress -hdd N
> and have attached a graph with up to 3000! stressors that
> we looked at this morning and another with up to 35 stressors.
>
> It's a crude indicators but once we get beyond 18-20 io stressors
> on the system I tested (48 cores, 128 GB RAM, 12 TB magnetic disk)
> dd time become erratic.
>
> Running qemu from tmpfs has clearly helped.
> Let's gather some data and decide if we want to spend more time
> learning how to monitor the system to tune how we are using it.
>
> ../Randy

Thanks for fixing the fall-out due to assumptions in other tests.
Is the system back to normal and operational now?


What was the impact of running the heartbeat and the dd test every
10 seconds on the system build performance?

Should we  increase the interval to 30, 60, ore more seconds?


I spent some time looking at the first bit of data along with
Sakib and Saul from time to time.

General conclusions:

1. It seems like ALL triggers involve oe-selftest being active.

2. xz might be a problem but we're not sure yet.

3. We need more data and tools and time to think about it.


To Do:

1. increase top cmdline length from 512 to  16K

2. sometimes we see:

      Command '['oe-time-dd-test.sh', '100']' timed out after 10.0 seconds

That should not happen so we should understand why and either increase
the time between runs or fix the tooling. This seems to happen under load
so it's hiding the interesting data that we are looking for!

3. tail the cooker console in addition to top. Present that before top.

     It would be nice to have a top equivalent for bitbake.




We did collect some triggered host data last night as seen in:

https://autobuilder.yocto.io/pub/non-release/

https://autobuilder.yocto.io/pub/non-release/20210415-16/

Only one a-full build was run. There were 10 log files produced.

There were 21 times that the dd time exceeded the 5 second limit
out of a total of 21581 (or so!) invocations and those triggers we
captured by 10 log files:

testresults/beaglebone-alt/2021-04-16--00-19/host_stats_0_top.txt
testresults/qa-extras2/2021-04-15--22-43/host_stats_2_top.txt
testresults/qa-extras2/2021-04-15--22-43/host_stats_4_top.txt
testresults/qa-extras2/2021-04-15--22-43/host_stats_6_top.txt
testresults/qa-extras2/2021-04-15--22-43/host_stats_8_top.txt
testresults/qemuarm/2021-04-16--00-02/host_stats_0_top.txt
testresults/qemuarm/2021-04-16--00-02/host_stats_1_top.txt
testresults/qemumips-alt/2021-04-15--23-36/host_stats_1_top.txt
testresults/qemumips64/2021-04-16--02-46/host_stats_0_top.txt
testresults/qemux86-world/2021-04-16--00-00/host_stats_0_top.txt


We knew that our naming convention needed work in that the files
are generically named and differ only by the directory datastamp and,
where the logs contain 'top' output or not the _top suffix.  We'd like 
to help
whoever is looking at the data understand what the context of
the build was. That's not clear to Sakib and I given that we are YP AB 
newbies still.
Do you have any suggestions about what the directory structure or file 
naming convention should be?
The other thing need to do is correlate these higher latency times
with the intermittent problems we've encountered. We can do that manually
I support via the SWAT team but ideally there would be an automated process.


More quick analysis...

The number of times that top ran per log file:

$ grep "^top - " `fd _top autobuilder.yocto.io/` | cut -d":" -f1 | uniq 
-c | \
     sed -e 's|autobuilder.yocto.io/pub/non-release/20210415-16/||'
       2 testresults/beaglebone-alt/2021-04-16--00-19/host_stats_0_top.txt
       3 testresults/qa-extras2/2021-04-15--22-43/host_stats_2_top.txt
       1 testresults/qa-extras2/2021-04-15--22-43/host_stats_4_top.txt
       2 testresults/qa-extras2/2021-04-15--22-43/host_stats_6_top.txt
       1 testresults/qa-extras2/2021-04-15--22-43/host_stats_8_top.txt
       5 testresults/qemuarm/2021-04-16--00-02/host_stats_0_top.txt
       2 testresults/qemuarm/2021-04-16--00-02/host_stats_1_top.txt
       1 testresults/qemumips-alt/2021-04-15--23-36/host_stats_1_top.txt
       2 testresults/qemumips64/2021-04-16--02-46/host_stats_0_top.txt
       2 testresults/qemux86-world/2021-04-16--00-00/host_stats_0_top.txt
some of these are duplicates in that the different steps _2,4,6,8 above

A little shell hacking can produce one file per top output with
ample access to stackoverflow!

COUNTER=1
for i in `fd _top`;
    do for j in `grep "^top - " $i | cut -c 7-15`; do
         sed -n "/top - ${j}/,/Event Time:/p" $i >> 
host-stats-$j--$COUNTER.log;
         ((COUNTER++));
    done;
done

This works because the first line of time is similar to:
    top - 15:40:53 up 2 days, 22:17,  1 user,  load average: 0.36, 0.58, 
0.85
so cutting out chars 7-15 gives a fairly uniq timestamp string for the 
filename and
adding the counter makes it unique.

Now we have 21 log files:

$ ls host-stats-2* | wc -l
21

How big are these files, ie how many process/kernel threads were running
when top ran?

$ wc -l host-stats-2* | sort -n
     757 host-stats-22:12:32--17.log
     778 host-stats-22:18:21--8.log
     784 host-stats-21:59:42--5.log
     785 host-stats-21:59:42--12.log
     792 host-stats-22:18:01--7.log
     800 host-stats-22:18:21--14.log
     811 host-stats-22:07:40--13.log
     812 host-stats-22:07:59--6.log
     821 host-stats-21:56:21--3.log
     850 host-stats-21:59:33--11.log
     856 host-stats-21:59:33--4.log
     869 host-stats-22:29:49--16.log
     884 host-stats-22:29:14--9.log
     886 host-stats-22:29:36--15.log
     981 host-stats-21:55:40--10.log
     985 host-stats-22:47:27--2.log
     987 host-stats-22:47:27--21.log
    1124 host-stats-22:37:33--1.log
    1193 host-stats-22:37:26--20.log
    1304 host-stats-23:19:14--19.log
    1321 host-stats-23:18:57--18.log
   19380 total

I noticed that several but not all log files were running xz with args like:

     xz -a --memlimit=50% --threads=56

$ for i in `ls host-stats-2*`; do echo -n $i ": "; grep "xz " $i | wc 
-l; done
host-stats-21:55:40--10.log : 28
host-stats-21:56:21--3.log : 4
host-stats-21:59:33--11.log : 1
host-stats-21:59:33--4.log : 1
host-stats-21:59:42--12.log : 1
host-stats-21:59:42--5.log : 1
host-stats-22:07:40--13.log : 2
host-stats-22:07:59--6.log : 2
host-stats-22:12:32--17.log : 0
host-stats-22:18:01--7.log : 6
host-stats-22:18:21--14.log : 3
host-stats-22:18:21--8.log : 3
host-stats-22:29:14--9.log : 1
host-stats-22:29:36--15.log : 0
host-stats-22:29:49--16.log : 0
host-stats-22:37:26--20.log : 56
host-stats-22:37:33--1.log : 16
host-stats-22:47:27--21.log : 0
host-stats-22:47:27--2.log : 0
host-stats-23:18:57--18.log : 0
host-stats-23:19:14--19.log : 18

In this case, I don't think it's a problem but if we had several packages
running xz like that at once with a limit of 50% of memory each,
that could be a problem. Has anyone looked at the time impact of
say reducing the number of threads to 32 and the memory limit to
15% ?


All of the top output logs seems to be running oe-selftest:

$ for i in host-stats-2*; do grep -H -c "DISPLAY.*oe-selftest " $i ; done
host-stats-21:55:40--10.log:1
host-stats-21:56:21--3.log:1
host-stats-21:59:33--11.log:1
host-stats-21:59:33--4.log:1
host-stats-21:59:42--12.log:1
host-stats-21:59:42--5.log:1
host-stats-22:07:40--13.log:1
host-stats-22:07:59--6.log:1
host-stats-22:12:32--17.log:1
host-stats-22:18:01--7.log:1
host-stats-22:18:21--14.log:1
host-stats-22:18:21--8.log:1
host-stats-22:29:14--9.log:1
host-stats-22:29:36--15.log:1
host-stats-22:29:49--16.log:1
host-stats-22:37:26--20.log:1
host-stats-22:37:33--1.log:1
host-stats-22:47:27--21.log:1
host-stats-22:47:27--2.log:1
host-stats-23:18:57--18.log:2
host-stats-23:19:14--19.log:2
$ for i in host-stats-2*; do grep -H -c "DISPLAY.*oe-selftest " $i ; 
done   | wc -l
21

Yikes, that seems like more than just random chance.


The logs do not seem to be duplicates in that there isn't a single cluster
of identical or similar timestamps although some are close and are
likely from the same file. That said they certainly don't seem to
be spread out uniformly over time and that's what we all expect
in that the system response time is okay for much of the time and
is poor for quite a while every now and then.

$ for i in host-stats-2*; do echo -n $i ": "; head -1 $i | cut -c -15; done
host-stats-21:55:40--10.log : top - 21:55:40
host-stats-21:56:21--3.log   : top - 21:56:21
host-stats-21:59:33--11.log : top - 21:59:33
host-stats-21:59:33--4.log   : top - 21:59:33
host-stats-21:59:42--12.log : top - 21:59:42
host-stats-21:59:42--5.log   : top - 21:59:42
host-stats-22:07:40--13.log : top - 22:07:40
host-stats-22:07:59--6.log   : top - 22:07:59
host-stats-22:12:32--17.log : top - 22:12:32
host-stats-22:18:01--7.log   : top - 22:18:01
host-stats-22:18:21--14.log : top - 22:18:21
host-stats-22:18:21--8.log   : top - 22:18:21
host-stats-22:29:14--9.log   : top - 22:29:14
host-stats-22:29:36--15.log : top - 22:29:36
host-stats-22:29:49--16.log : top - 22:29:49
host-stats-22:37:26--20.log : top - 22:37:26
host-stats-22:37:33--1.log   : top - 22:37:33
host-stats-22:47:27--21.log : top - 22:47:27
host-stats-22:47:27--2.log   : top - 22:47:27
host-stats-23:18:57--18.log : top - 23:18:57
host-stats-23:19:14--19.log : top - 23:19:14


All for now.

../Randy


>
>>
>> ../Randy
>>>>>
>>>>> Cheers,
>>>>>
>>>>> Richard
>>>>
>>>> The template is not used anywhere, yet, the initial patchset 
>>>> enables the
>>>> data collection by default.
>>>>
>>>> I have left the template in case the data collection is removed from
>>>> defaults and need to be used on a case by case basis.
>>>>
>>>> I am not entirely sure if nesting templates work. I have not seen any
>>>> examples of it, neither did i try it myself. If nesting does work, the
>>>> template should be useful.
>>>
>>> I had a quick look at the code and sadly, it doesn't appear I 
>>> implemented
>>> nesting so this wouldn't be that useful as things stand.
>>>
>>> Cheers,
>>>
>>> Richard
>>>
>>>
>>>
>>>
>>> 
>>>
>>
>>
>
>

-- 
# Randy MacLeod
# Wind River Linux

Re: [yocto] [PATCH yocto-autobuilder-helper 1/4] config.json: add "collect-data" template -- Build: 20210420-1

[Randy MacLeod]

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

Summary:

Build: 20210420-1 had 23 triggers and isn't really worth
analyzing. Stay tuned for what is hopefully better data
with a higher timeout threshold.

There is a nice looking pair of graph attached though! :)

../Randy

On 2021-04-15 4:48 p.m., Randy MacLeod wrote:
> On 2021-04-15 1:55 p.m., Randy MacLeod wrote:


 > Should we  increase the interval to 30, 60, ore more seconds?

I've bumped the interval to 60 seconds.


I spent some time looking at the first bit of data along with
Sakib and Saul from time to time.
> General conclusions:
> 
> 1. It seems like ALL triggers involve oe-selftest being active.

Still true.
> 
> 2. xz might be a problem but we're not sure yet. 

Added to graph attached.

> 
> 3. We need more data and tools and time to think about it.



> To Do:
> 
> 1. increase top cmdline length from 512 to  16K

Still to do, maybe. It's not clear that it's useful yet.

> 
> 2. sometimes we see:
> 
>      Command '['oe-time-dd-test.sh', '100']' timed out after 10.0 seconds
> 
> That should not happen so we should understand why and either increase
> the time between runs or fix the tooling. This seems to happen under load
> so it's hiding the interesting data that we are looking for!

With a 60 second interval, this does NOT happen.

> 
> 3. tail the cooker console in addition to top. Present that before top.
> 
>     It would be nice to have a top equivalent for bitbake.

Still to do.
This can be done via the cooker log.
We can parse the file and do:
1. list recent tasks regardless of whether they have completed:
       tail -20?
2. list tasks that have started but not completed.



This email is about:
    https://autobuilder.yocto.io/pub/non-release/20210420-1/
It was a 'quick' build. There was only 1 log file produced.
It used the master so the timeout was still 5 seconds.

There were 23 (!!) times that the dd time exceeded the
15 (ACTUALLY 5) second limit out of a total of 1504 invocations
and those triggers were captured by 1 log file:
    testresults/qemux86-world/2021-04-20--03-43/host_stats_0_top.txt


Splitting each top output into a separate file as before,
now we have 23 log files:

How big are these files, ie how many process/kernel threads were running
when top ran?

$ wc -l host-stats-0* | sort -n
     699 host-stats-03:42:40--23.log
     704 host-stats-02:20:41--5.log
     720 host-stats-03:33:41--21.log
     733 host-stats-02:19:40--4.log
     743 host-stats-03:32:41--20.log
     752 host-stats-02:25:45--6.log
     753 host-stats-02:02:46--3.log
     760 host-stats-03:36:07--22.log
     784 host-stats-02:01:48--2.log
     784 host-stats-03:30:43--18.log
     802 host-stats-02:45:55--10.log
     807 host-stats-03:31:42--19.log
     816 host-stats-03:29:49--17.log
     829 host-stats-03:19:50--15.log
     845 host-stats-02:41:40--8.log
     851 host-stats-02:00:57--1.log
     899 host-stats-02:32:47--7.log
     906 host-stats-03:18:41--14.log
     925 host-stats-03:28:24--16.log
     947 host-stats-02:42:41--9.log
    1084 host-stats-03:16:50--13.log
    1204 host-stats-02:54:43--11.log
    1314 host-stats-03:03:41--12.log
   19661 total



I noticed that several but not all log files were running xz:

$ for i in `ls host-stats-*`; do echo -n $i ": "; grep "xz " $i | wc -l; 
done
host-stats-02:00:57--1.log : 0
host-stats-02:01:48--2.log : 0
host-stats-02:02:46--3.log : 0
host-stats-02:19:40--4.log : 2
host-stats-02:20:41--5.log : 0
host-stats-02:25:45--6.log : 2
host-stats-02:32:47--7.log : 0
host-stats-02:41:40--8.log : 1
host-stats-02:42:41--9.log : 2
host-stats-02:45:55--10.log : 1
host-stats-02:54:43--11.log : 0
host-stats-03:03:41--12.log : 0
host-stats-03:16:50--13.log : 47
host-stats-03:18:41--14.log : 0
host-stats-03:19:50--15.log : 9
host-stats-03:28:24--16.log : 15
host-stats-03:29:49--17.log : 0
host-stats-03:30:43--18.log : 0
host-stats-03:31:42--19.log : 7
host-stats-03:32:41--20.log : 7
host-stats-03:33:41--21.log : 11
host-stats-03:36:07--22.log : 15
host-stats-03:42:40--23.log : 9


I've plotted the number of xz processes along with the load average
and the dd time  in the attached graph.


All of the top output logs seems to be running oe-selftest:

for i in host-stats-0*; do grep -H -c "DISPLAY.*oe-selftest " $i ; done
host-stats-02:00:57--1.log:1
host-stats-02:01:48--2.log:1
host-stats-02:02:46--3.log:1
host-stats-02:19:40--4.log:1
host-stats-02:20:41--5.log:1
host-stats-02:25:45--6.log:1
host-stats-02:32:47--7.log:1
host-stats-02:41:40--8.log:2
host-stats-02:42:41--9.log:2
host-stats-02:45:55--10.log:2
host-stats-02:54:43--11.log:2
host-stats-03:03:41--12.log:2
host-stats-03:16:50--13.log:2
host-stats-03:18:41--14.log:2
host-stats-03:19:50--15.log:2
host-stats-03:28:24--16.log:2
host-stats-03:29:49--17.log:2
host-stats-03:30:43--18.log:2
host-stats-03:31:42--19.log:2
host-stats-03:32:41--20.log:2
host-stats-03:33:41--21.log:2
host-stats-03:36:07--22.log:2
host-stats-03:42:40--23.log:2



The logs DO seem to be clustered in that there are several 1 minute 
adjacent intervals where the dd time exceeded the threshold.

Data here but you can see this in the attached graph.

$ for i in host-stats-*; do echo -n $i ": "; head -1 $i | cut -c -15; done
host-stats-02:00:57--1.log : top - 02:00:57
host-stats-02:01:48--2.log : top - 02:01:48
host-stats-02:02:46--3.log : top - 02:02:46
host-stats-02:19:40--4.log : top - 02:19:40
host-stats-02:20:41--5.log : top - 02:20:41
host-stats-02:25:45--6.log : top - 02:25:45
host-stats-02:32:47--7.log : top - 02:32:47
host-stats-02:41:40--8.log : top - 02:41:40
host-stats-02:42:41--9.log : top - 02:42:41
host-stats-02:45:55--10.log : top - 02:45:55
host-stats-02:54:43--11.log : top - 02:54:43
host-stats-03:03:41--12.log : top - 03:03:41
host-stats-03:16:50--13.log : top - 03:16:50
host-stats-03:18:41--14.log : top - 03:18:41
host-stats-03:19:50--15.log : top - 03:19:50
host-stats-03:28:24--16.log : top - 03:28:24
host-stats-03:29:49--17.log : top - 03:29:49
host-stats-03:30:43--18.log : top - 03:30:43
host-stats-03:31:42--19.log : top - 03:31:42
host-stats-03:32:41--20.log : top - 03:32:41
host-stats-03:33:41--21.log : top - 03:33:41
host-stats-03:36:07--22.log : top - 03:36:07
host-stats-03:42:40--23.log : top - 03:42:40



*** Add time distribution of dd.
Oddly enough, the output of dd does not seem to be consistent:

102400 bytes (102 kB) copied, 0.0163975 s, 6.2 MB/s
102400 bytes (102 kB) copied, 0.0054732 s, 18.7 MB/s
102400 bytes (102 kB, 100 KiB) copied, 0.0984687 s, 1.0 MB/s
102400 bytes (102 kB, 100 KiB) copied, 0.304233 s, 337 kB/s

I'm not sure what's going on there, yet. Sakib?


I think the cooker output will be quite useful.
I'm not going to put any more time into this data set
since the time threshold is still 5 seconds.

All for now.

../Randy


>
>>
>> ../Randy
>>>>>
>>>>> Cheers,
>>>>>
>>>>> Richard
>>>>
>>>> The template is not used anywhere, yet, the initial patchset 
>>>> enables the
>>>> data collection by default.
>>>>
>>>> I have left the template in case the data collection is removed from
>>>> defaults and need to be used on a case by case basis.
>>>>
>>>> I am not entirely sure if nesting templates work. I have not seen any
>>>> examples of it, neither did i try it myself. If nesting does work, the
>>>> template should be useful.
>>>
>>> I had a quick look at the code and sadly, it doesn't appear I 
>>> implemented
>>> nesting so this wouldn't be that useful as things stand.
>>>
>>> Cheers,
>>>
>>> Richard
>>>
>>>
>>>
>>>
>>> 
>>>
>>
>>
>
>

-- 
# Randy MacLeod
# Wind River Linux


[-- Attachment #2: time-dd-latency-distribution-20210420-1.png --]
[-- Type: image/png, Size: 8344 bytes --]

[-- Attachment #3: load-average-dd-time-2021-04-20--1.png --]
[-- Type: image/png, Size: 17155 bytes --]