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@... 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@...>
Signed-off-by: Randy MacLeod <Randy.MacLeod@...>
---
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

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@... 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@...>
Signed-off-by: Randy MacLeod <Randy.MacLeod@...>
---
   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

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@... 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@...>
Signed-off-by: Randy MacLeod <Randy.MacLeod@...>
---
   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

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@... 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@...>
Signed-off-by: Randy MacLeod <Randy.MacLeod@...>
---
  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

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@... 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@...>
Signed-off-by: Randy MacLeod <Randy.MacLeod@...>
---
  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

On Tue, 2021-04-13 at 13:02 -0400, sakib.sajal@... 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@...>
Signed-off-by: Randy MacLeod <Randy.MacLeod@...>
---
 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

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@...>
Signed-off-by: Randy MacLeod <Randy.MacLeod@...>
---
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